From 90191a661c864e1c0ffe124ef1229157195e6e56 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 16:00:02 -0400 Subject: [PATCH 01/21] Add Sunshine pairing diagnostics --- src/confighttp.cpp | 14 +- src/nvhttp.cpp | 472 ++++++++++++++++++++++++++++++++++++--------- 2 files changed, 391 insertions(+), 95 deletions(-) diff --git a/src/confighttp.cpp b/src/confighttp.cpp index 32f504ee699..38940f4456e 100644 --- a/src/confighttp.cpp +++ b/src/confighttp.cpp @@ -1341,16 +1341,28 @@ namespace confighttp { nlohmann::json input_tree = nlohmann::json::parse(ss); const std::string name = input_tree.value("name", ""); const std::string pin = input_tree.value("pin", ""); + BOOST_LOG(info) << "PAIR_DIAG /api/pin API handler received name="sv << (name.empty() ? ""s : name) + << " missing_name="sv << name.empty() + << " pin_len="sv << pin.size() + << " web_client_id="sv << client_id; int _pin = 0; _pin = std::stoi(pin); if (_pin < 0 || _pin > 9999) { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin API handler rejected reason=pin outside 0000-9999 pin_len="sv << pin.size(); bad_request(response, request, "PIN must be between 0000 and 9999"); } - output_tree["status"] = nvhttp::pin(pin, name); + const auto pin_status = nvhttp::pin(pin, name); + if (pin_status) { + BOOST_LOG(info) << "PAIR_DIAG /api/pin API handler completed status=true name="sv << (name.empty() ? ""s : name); + } else { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin API handler completed status=false name="sv << (name.empty() ? ""s : name); + } + output_tree["status"] = pin_status; send_response(response, output_tree); } catch (std::exception &e) { + BOOST_LOG(error) << "PAIR_DIAG exception in /api/pin API handler: "sv << e.what(); BOOST_LOG(warning) << "SavePin: "sv << e.what(); bad_request(response, request, e.what()); } diff --git a/src/nvhttp.cpp b/src/nvhttp.cpp index 4db8c6e4e94..7d118db989b 100644 --- a/src/nvhttp.cpp +++ b/src/nvhttp.cpp @@ -150,6 +150,46 @@ namespace nvhttp { using resp_http_t = std::shared_ptr::Response>; using req_http_t = std::shared_ptr::Request>; + const char *pair_phase_name(PAIR_PHASE phase) { + switch (phase) { + case PAIR_PHASE::NONE: + return "NONE"; + case PAIR_PHASE::GETSERVERCERT: + return "GETSERVERCERT"; + case PAIR_PHASE::CLIENTCHALLENGE: + return "CLIENTCHALLENGE"; + case PAIR_PHASE::SERVERCHALLENGERESP: + return "SERVERCHALLENGERESP"; + case PAIR_PHASE::CLIENTPAIRINGSECRET: + return "CLIENTPAIRINGSECRET"; + } + + return "UNKNOWN"; + } + + std::string diag_value(std::string_view value) { + return value.empty() ? ""s : std::string(value); + } + + std::string get_optional_arg(const args_t &args, const char *name) { + auto it = args.find(name); + if (it == std::end(args)) { + return {}; + } + + return it->second; + } + + void log_pair_session_marker(std::string_view marker, const pair_session_t &sess) { + BOOST_LOG(info) << "PAIR_DIAG "sv << marker + << " session_key="sv << diag_value(sess.client.uniqueID) + << " client_name="sv << diag_value(sess.client.name) + << " client_cert_len="sv << sess.client.cert.size() + << " salt_len="sv << sess.async_insert_pin.salt.size() + << " phase="sv << pair_phase_name(sess.last_phase) + << " active_sessions="sv << map_id_sess.size(); + } + enum class op_e { ADD, ///< Add certificate REMOVE ///< Remove certificate @@ -168,12 +208,16 @@ namespace nvhttp { } void save_state() { + BOOST_LOG(info) << "PAIR_DIAG save_state begin path="sv << config::nvhttp.file_state + << " authorized_clients="sv << client_root.named_devices.size(); + pt::ptree root; if (fs::exists(config::nvhttp.file_state)) { try { pt::read_json(config::nvhttp.file_state, root); } catch (std::exception &e) { + BOOST_LOG(error) << "PAIR_DIAG save_state failed while reading path="sv << config::nvhttp.file_state << ": "sv << e.what(); BOOST_LOG(error) << "Couldn't read "sv << config::nvhttp.file_state << ": "sv << e.what(); return; } @@ -199,9 +243,13 @@ namespace nvhttp { try { pt::write_json(config::nvhttp.file_state, root); } catch (std::exception &e) { + BOOST_LOG(error) << "PAIR_DIAG save_state failed while writing path="sv << config::nvhttp.file_state << ": "sv << e.what(); BOOST_LOG(error) << "Couldn't write "sv << config::nvhttp.file_state << ": "sv << e.what(); return; } + + BOOST_LOG(info) << "PAIR_DIAG save_state succeeded path="sv << config::nvhttp.file_state + << " authorized_clients="sv << client_root.named_devices.size(); } void load_state() { @@ -270,6 +318,11 @@ namespace nvhttp { } void add_authorized_client(const std::string &name, std::string &&cert) { + const auto cert_len = cert.size(); + BOOST_LOG(info) << "PAIR_DIAG add_authorized_client called name="sv << diag_value(name) + << " cert_len="sv << cert_len + << " authorized_clients_before="sv << client_root.named_devices.size(); + client_t &client = client_root; named_cert_t named_cert; named_cert.name = name; @@ -277,8 +330,16 @@ namespace nvhttp { named_cert.uuid = uuid_util::uuid_t::generate().string(); client.named_devices.emplace_back(named_cert); + BOOST_LOG(info) << "PAIR_DIAG add_authorized_client added name="sv << diag_value(client.named_devices.back().name) + << " uuid="sv << client.named_devices.back().uuid + << " cert_len="sv << cert_len + << " authorized_clients_after="sv << client.named_devices.size(); + if (!config::sunshine.flags[config::flag::FRESH_STATE]) { + BOOST_LOG(info) << "PAIR_DIAG add_authorized_client invoking save_state path="sv << config::nvhttp.file_state; save_state(); + } else { + BOOST_LOG(warning) << "PAIR_DIAG add_authorized_client skipped save_state because FRESH_STATE is set"; } } @@ -341,10 +402,21 @@ namespace nvhttp { } void remove_session(const pair_session_t &sess) { - map_id_sess.erase(sess.client.uniqueID); + const auto session_key = sess.client.uniqueID; + const auto before = map_id_sess.size(); + const auto erased = map_id_sess.erase(session_key); + BOOST_LOG(info) << "PAIR_DIAG remove_session session_key="sv << diag_value(session_key) + << " erased="sv << erased + << " active_sessions_before="sv << before + << " active_sessions_after="sv << map_id_sess.size(); } void fail_pair(pair_session_t &sess, pt::ptree &tree, const std::string status_msg) { + BOOST_LOG(warning) << "PAIR_DIAG pairing rejected session_key="sv << diag_value(sess.client.uniqueID) + << " reason="sv << status_msg + << " phase="sv << pair_phase_name(sess.last_phase) + << " client_name="sv << diag_value(sess.client.name) + << " active_sessions="sv << map_id_sess.size(); tree.put("root.paired", 0); tree.put("root..status_code", 400); tree.put("root..status_message", status_msg); @@ -352,13 +424,25 @@ namespace nvhttp { } void getservercert(pair_session_t &sess, pt::ptree &tree, const std::string &pin) { + log_pair_session_marker("getservercert reached", sess); + BOOST_LOG(info) << "PAIR_DIAG getservercert map_id_sess size before="sv << map_id_sess.size() + << " pin_len="sv << pin.size(); + if (sess.last_phase != PAIR_PHASE::NONE) { + BOOST_LOG(warning) << "PAIR_DIAG getservercert rejected bad phase session_key="sv << diag_value(sess.client.uniqueID) + << " phase_before="sv << pair_phase_name(sess.last_phase); fail_pair(sess, tree, "Out of order call to getservercert"); return; } + const auto phase_before = sess.last_phase; sess.last_phase = PAIR_PHASE::GETSERVERCERT; + BOOST_LOG(info) << "PAIR_DIAG phase transition session_key="sv << diag_value(sess.client.uniqueID) + << " from="sv << pair_phase_name(phase_before) + << " to="sv << pair_phase_name(sess.last_phase); if (sess.async_insert_pin.salt.size() < 32) { + BOOST_LOG(warning) << "PAIR_DIAG getservercert rejected salt too short session_key="sv << diag_value(sess.client.uniqueID) + << " salt_len="sv << sess.async_insert_pin.salt.size(); fail_pair(sess, tree, "Salt too short"); return; } @@ -373,16 +457,31 @@ namespace nvhttp { tree.put("root.paired", 1); tree.put("root.plaincert", util::hex_vec(conf_intern.servercert, true)); tree.put("root..status_code", 200); + + BOOST_LOG(info) << "PAIR_DIAG getservercert accepted session_key="sv << diag_value(sess.client.uniqueID) + << " phase_after="sv << pair_phase_name(sess.last_phase) + << " map_id_sess size after="sv << map_id_sess.size(); } void clientchallenge(pair_session_t &sess, pt::ptree &tree, const std::string &challenge) { + log_pair_session_marker("clientchallenge reached", sess); + BOOST_LOG(info) << "PAIR_DIAG clientchallenge payload_len="sv << challenge.size() + << " phase_before="sv << pair_phase_name(sess.last_phase); + if (sess.last_phase != PAIR_PHASE::GETSERVERCERT) { + BOOST_LOG(warning) << "PAIR_DIAG clientchallenge rejected bad phase session_key="sv << diag_value(sess.client.uniqueID) + << " phase_before="sv << pair_phase_name(sess.last_phase); fail_pair(sess, tree, "Out of order call to clientchallenge"); return; } + const auto phase_before = sess.last_phase; sess.last_phase = PAIR_PHASE::CLIENTCHALLENGE; + BOOST_LOG(info) << "PAIR_DIAG phase transition session_key="sv << diag_value(sess.client.uniqueID) + << " from="sv << pair_phase_name(phase_before) + << " to="sv << pair_phase_name(sess.last_phase); if (!sess.cipher_key) { + BOOST_LOG(warning) << "PAIR_DIAG clientchallenge rejected cipher key missing session_key="sv << diag_value(sess.client.uniqueID); fail_pair(sess, tree, "Cipher key not set"); return; } @@ -416,16 +515,34 @@ namespace nvhttp { tree.put("root.paired", 1); tree.put("root.challengeresponse", util::hex_vec(encrypted, true)); tree.put("root..status_code", 200); + + BOOST_LOG(info) << "PAIR_DIAG clientchallenge accepted session_key="sv << diag_value(sess.client.uniqueID) + << " phase_after="sv << pair_phase_name(sess.last_phase) + << " serversecret_len="sv << sess.serversecret.size() + << " serverchallenge_len="sv << sess.serverchallenge.size(); } void serverchallengeresp(pair_session_t &sess, pt::ptree &tree, const std::string &encrypted_response) { + log_pair_session_marker("serverchallengeresp reached", sess); + BOOST_LOG(info) << "PAIR_DIAG serverchallengeresp payload_len="sv << encrypted_response.size() + << " phase_before="sv << pair_phase_name(sess.last_phase); + if (sess.last_phase != PAIR_PHASE::CLIENTCHALLENGE) { + BOOST_LOG(warning) << "PAIR_DIAG serverchallengeresp rejected bad phase session_key="sv << diag_value(sess.client.uniqueID) + << " phase_before="sv << pair_phase_name(sess.last_phase); fail_pair(sess, tree, "Out of order call to serverchallengeresp"); return; } + const auto phase_before = sess.last_phase; sess.last_phase = PAIR_PHASE::SERVERCHALLENGERESP; + BOOST_LOG(info) << "PAIR_DIAG phase transition session_key="sv << diag_value(sess.client.uniqueID) + << " from="sv << pair_phase_name(phase_before) + << " to="sv << pair_phase_name(sess.last_phase); if (!sess.cipher_key || sess.serversecret.empty()) { + BOOST_LOG(warning) << "PAIR_DIAG serverchallengeresp rejected missing crypto state session_key="sv << diag_value(sess.client.uniqueID) + << " has_cipher_key="sv << static_cast(sess.cipher_key) + << " serversecret_len="sv << sess.serversecret.size(); fail_pair(sess, tree, "Cipher key or serversecret not set"); return; } @@ -445,18 +562,34 @@ namespace nvhttp { tree.put("root.pairingsecret", util::hex_vec(serversecret, true)); tree.put("root.paired", 1); tree.put("root..status_code", 200); + + BOOST_LOG(info) << "PAIR_DIAG serverchallengeresp accepted session_key="sv << diag_value(sess.client.uniqueID) + << " phase_after="sv << pair_phase_name(sess.last_phase) + << " clienthash_len="sv << sess.clienthash.size(); } void clientpairingsecret(pair_session_t &sess, std::shared_ptr> &add_cert, pt::ptree &tree, const std::string &client_pairing_secret) { + log_pair_session_marker("clientpairingsecret reached", sess); + BOOST_LOG(info) << "PAIR_DIAG clientpairingsecret payload_len="sv << client_pairing_secret.size() + << " phase_before="sv << pair_phase_name(sess.last_phase); + if (sess.last_phase != PAIR_PHASE::SERVERCHALLENGERESP) { + BOOST_LOG(warning) << "PAIR_DIAG clientpairingsecret rejected bad phase session_key="sv << diag_value(sess.client.uniqueID) + << " phase_before="sv << pair_phase_name(sess.last_phase); fail_pair(sess, tree, "Out of order call to clientpairingsecret"); return; } + const auto phase_before = sess.last_phase; sess.last_phase = PAIR_PHASE::CLIENTPAIRINGSECRET; + BOOST_LOG(info) << "PAIR_DIAG phase transition session_key="sv << diag_value(sess.client.uniqueID) + << " from="sv << pair_phase_name(phase_before) + << " to="sv << pair_phase_name(sess.last_phase); auto &client = sess.client; if (client_pairing_secret.size() <= 16) { + BOOST_LOG(warning) << "PAIR_DIAG clientpairingsecret rejected secret too short session_key="sv << diag_value(sess.client.uniqueID) + << " payload_len="sv << client_pairing_secret.size(); fail_pair(sess, tree, "Client pairing secret too short"); return; } @@ -466,6 +599,9 @@ namespace nvhttp { auto x509 = crypto::x509(client.cert); if (!x509) { + BOOST_LOG(warning) << "PAIR_DIAG clientpairingsecret rejected invalid client certificate session_key="sv << diag_value(sess.client.uniqueID) + << " client_name="sv << diag_value(client.name) + << " cert_len="sv << client.cert.size(); fail_pair(sess, tree, "Invalid client certificate"); return; } @@ -483,18 +619,31 @@ namespace nvhttp { // if hash not correct, probably MITM bool same_hash = hash.size() == sess.clienthash.size() && std::equal(hash.begin(), hash.end(), sess.clienthash.begin()); auto verify = crypto::verify256(crypto::x509(client.cert), secret, sign); + BOOST_LOG(info) << "PAIR_DIAG clientpairingsecret verification session_key="sv << diag_value(sess.client.uniqueID) + << " same_hash="sv << same_hash + << " verify_signature="sv << verify + << " client_name="sv << diag_value(client.name); if (same_hash && verify) { tree.put("root.paired", 1); add_cert->raise(crypto::x509(client.cert)); // The client is now successfully paired and will be authorized to connect + BOOST_LOG(info) << "PAIR_DIAG clientpairingsecret accepted; calling add_authorized_client session_key="sv << diag_value(sess.client.uniqueID) + << " client_name="sv << diag_value(client.name); add_authorized_client(client.name, std::move(client.cert)); } else { + BOOST_LOG(warning) << "PAIR_DIAG clientpairingsecret rejected verification failed session_key="sv << diag_value(sess.client.uniqueID) + << " same_hash="sv << same_hash + << " verify_signature="sv << verify; tree.put("root.paired", 0); } + const auto final_session_key = sess.client.uniqueID; + const auto final_phase = sess.last_phase; remove_session(sess); tree.put("root..status_code", 200); + BOOST_LOG(info) << "PAIR_DIAG clientpairingsecret complete session_key="sv << diag_value(final_session_key) + << " phase_after="sv << pair_phase_name(final_phase); } template @@ -563,121 +712,256 @@ namespace nvhttp { response->close_connection_after_response = true; }); - auto args = request->parse_query_string(); - if (args.find("uniqueid"s) == std::end(args)) { - tree.put("root..status_code", 400); - tree.put("root..status_message", "Missing uniqueid parameter"); - - return; - } - - auto uniqID {get_arg(args, "uniqueid")}; - - args_t::const_iterator it; - if (it = args.find("phrase"); it != std::end(args)) { - if (it->second == "getservercert"sv) { - pair_session_t sess; - - sess.client.uniqueID = std::move(uniqID); - sess.client.cert = util::from_hex_vec(get_arg(args, "clientcert"), true); - - BOOST_LOG(debug) << sess.client.cert; - auto ptr = map_id_sess.emplace(sess.client.uniqueID, std::move(sess)).first; - - ptr->second.async_insert_pin.salt = std::move(get_arg(args, "salt")); - if (config::sunshine.flags[config::flag::PIN_STDIN]) { - std::string pin; + try { + auto args = request->parse_query_string(); + const auto uniqueid_arg = get_optional_arg(args, "uniqueid"); + const auto phrase_arg = get_optional_arg(args, "phrase"); + const auto devicename_arg = get_optional_arg(args, "devicename"); + const auto name_arg = get_optional_arg(args, "name"); + const auto uuid_arg = get_optional_arg(args, "uuid"); + + BOOST_LOG(info) << "PAIR_DIAG /pair request uniqueid="sv << diag_value(uniqueid_arg) + << " phrase="sv << diag_value(phrase_arg) + << " devicename="sv << diag_value(devicename_arg) + << " name="sv << diag_value(name_arg) + << " uuid="sv << diag_value(uuid_arg) + << " active_sessions="sv << map_id_sess.size(); + + if (args.find("uniqueid"s) == std::end(args)) { + BOOST_LOG(warning) << "PAIR_DIAG /pair rejected reason=missing uniqueid active_sessions="sv << map_id_sess.size(); + tree.put("root..status_code", 400); + tree.put("root..status_message", "Missing uniqueid parameter"); - std::cout << "Please insert pin: "sv; - std::getline(std::cin, pin); + return; + } - getservercert(ptr->second, tree, pin); - return; - } else { + auto uniqID {get_arg(args, "uniqueid")}; + + args_t::const_iterator it; + if (it = args.find("phrase"); it != std::end(args)) { + if (it->second == "getservercert"sv) { + pair_session_t sess; + + sess.client.uniqueID = std::move(uniqID); + sess.client.cert = util::from_hex_vec(get_arg(args, "clientcert"), true); + + const auto session_key = sess.client.uniqueID; + const auto client_cert_len = sess.client.cert.size(); + const auto sessions_before = map_id_sess.size(); + BOOST_LOG(info) << "PAIR_DIAG creating pairing session session_key="sv << diag_value(session_key) + << " client_cert_len="sv << client_cert_len + << " devicename="sv << diag_value(devicename_arg) + << " name="sv << diag_value(name_arg) + << " uuid="sv << diag_value(uuid_arg) + << " active_sessions_before="sv << sessions_before; + + BOOST_LOG(debug) << sess.client.cert; + auto [ptr, inserted] = map_id_sess.emplace(sess.client.uniqueID, std::move(sess)); + + BOOST_LOG(info) << "PAIR_DIAG pairing session created session_key="sv << diag_value(session_key) + << " inserted="sv << inserted + << " active_sessions_before="sv << sessions_before + << " active_sessions_after="sv << map_id_sess.size() + << " stored_phase="sv << pair_phase_name(ptr->second.last_phase); + + ptr->second.async_insert_pin.salt = std::move(get_arg(args, "salt")); + log_pair_session_marker("getservercert session ready for PIN", ptr->second); + if (config::sunshine.flags[config::flag::PIN_STDIN]) { + std::string pin; + + std::cout << "Please insert pin: "sv; + std::getline(std::cin, pin); + + BOOST_LOG(info) << "PAIR_DIAG map_id_sess size before getservercert="sv << map_id_sess.size() + << " source=stdin session_key="sv << diag_value(session_key); + getservercert(ptr->second, tree, pin); + BOOST_LOG(info) << "PAIR_DIAG map_id_sess size after getservercert="sv << map_id_sess.size() + << " source=stdin session_key="sv << diag_value(session_key); + return; + } else { #if defined SUNSHINE_TRAY && SUNSHINE_TRAY >= 1 - system_tray::update_tray_require_pin(); + system_tray::update_tray_require_pin(); #endif - ptr->second.async_insert_pin.response = std::move(response); + ptr->second.async_insert_pin.response = std::move(response); - fg.disable(); + BOOST_LOG(info) << "PAIR_DIAG getservercert waiting for /api/pin session_key="sv << diag_value(session_key) + << " active_sessions="sv << map_id_sess.size() + << " async_response_stored=1"; + fg.disable(); + return; + } + } else if (it->second == "pairchallenge"sv) { + BOOST_LOG(info) << "PAIR_DIAG pairchallenge acknowledged uniqueid="sv << diag_value(uniqID) + << " active_sessions="sv << map_id_sess.size(); + tree.put("root.paired", 1); + tree.put("root..status_code", 200); return; } - } else if (it->second == "pairchallenge"sv) { - tree.put("root.paired", 1); - tree.put("root..status_code", 200); - return; } - } - auto sess_it = map_id_sess.find(uniqID); - if (sess_it == std::end(map_id_sess)) { - tree.put("root..status_code", 400); - tree.put("root..status_message", "Invalid uniqueid"); + BOOST_LOG(info) << "PAIR_DIAG looking up active session uniqueid="sv << diag_value(uniqID) + << " active_sessions="sv << map_id_sess.size(); + auto sess_it = map_id_sess.find(uniqID); + if (sess_it == std::end(map_id_sess)) { + BOOST_LOG(warning) << "PAIR_DIAG /pair rejected reason=no active session or session already cleaned up uniqueid="sv << diag_value(uniqID) + << " active_sessions="sv << map_id_sess.size(); + tree.put("root..status_code", 400); + tree.put("root..status_message", "Invalid uniqueid"); - return; - } + return; + } - if (it = args.find("clientchallenge"); it != std::end(args)) { - auto challenge = util::from_hex_vec(it->second, true); - clientchallenge(sess_it->second, tree, challenge); - } else if (it = args.find("serverchallengeresp"); it != std::end(args)) { - auto encrypted_response = util::from_hex_vec(it->second, true); - serverchallengeresp(sess_it->second, tree, encrypted_response); - } else if (it = args.find("clientpairingsecret"); it != std::end(args)) { - auto pairingsecret = util::from_hex_vec(it->second, true); - clientpairingsecret(sess_it->second, add_cert, tree, pairingsecret); - } else { - tree.put("root..status_code", 404); - tree.put("root..status_message", "Invalid pairing request"); + log_pair_session_marker("/pair session found", sess_it->second); + if (it = args.find("clientchallenge"); it != std::end(args)) { + BOOST_LOG(info) << "PAIR_DIAG dispatch clientchallenge session_key="sv << diag_value(sess_it->second.client.uniqueID) + << " hex_len="sv << it->second.size(); + auto challenge = util::from_hex_vec(it->second, true); + clientchallenge(sess_it->second, tree, challenge); + } else if (it = args.find("serverchallengeresp"); it != std::end(args)) { + BOOST_LOG(info) << "PAIR_DIAG dispatch serverchallengeresp session_key="sv << diag_value(sess_it->second.client.uniqueID) + << " hex_len="sv << it->second.size(); + auto encrypted_response = util::from_hex_vec(it->second, true); + serverchallengeresp(sess_it->second, tree, encrypted_response); + } else if (it = args.find("clientpairingsecret"); it != std::end(args)) { + BOOST_LOG(info) << "PAIR_DIAG dispatch clientpairingsecret session_key="sv << diag_value(sess_it->second.client.uniqueID) + << " hex_len="sv << it->second.size(); + auto pairingsecret = util::from_hex_vec(it->second, true); + clientpairingsecret(sess_it->second, add_cert, tree, pairingsecret); + } else { + BOOST_LOG(warning) << "PAIR_DIAG /pair rejected reason=invalid pairing request uniqueid="sv << diag_value(uniqID) + << " active_sessions="sv << map_id_sess.size(); + tree.put("root..status_code", 404); + tree.put("root..status_message", "Invalid pairing request"); + } + } catch (std::exception &e) { + BOOST_LOG(error) << "PAIR_DIAG exception in /pair: "sv << e.what() + << " active_sessions="sv << map_id_sess.size(); + tree.put("root..status_code", 500); + tree.put("root..status_message", std::format("Pairing exception: {}", e.what())); + } catch (...) { + BOOST_LOG(error) << "PAIR_DIAG unknown exception in /pair active_sessions="sv << map_id_sess.size(); + tree.put("root..status_code", 500); + tree.put("root..status_message", "Unknown pairing exception"); } } bool pin(std::string pin, std::string name) { - pt::ptree tree; - if (map_id_sess.empty()) { - return false; - } + try { + pt::ptree tree; + const auto sessions_before = map_id_sess.size(); + BOOST_LOG(info) << "PAIR_DIAG /api/pin received name="sv << diag_value(name) + << " missing_name="sv << name.empty() + << " pin_len="sv << pin.size() + << " active_sessions_before="sv << sessions_before; + + if (map_id_sess.empty()) { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected reason=no active pairing session; session may be expired or already cleaned up" + << " active_sessions_before="sv << sessions_before + << " active_sessions_after="sv << map_id_sess.size(); + return false; + } - // ensure pin is 4 digits - if (pin.size() != 4) { - tree.put("root.paired", 0); - tree.put("root..status_code", 400); - tree.put( - "root..status_message", - std::format("Pin must be 4 digits, {} provided", pin.size()) - ); - return false; - } + if (name.empty()) { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin name field is empty; continuing with existing behavior"; + } - // ensure all pin characters are numeric - if (!std::all_of(pin.begin(), pin.end(), ::isdigit)) { - tree.put("root.paired", 0); - tree.put("root..status_code", 400); - tree.put("root..status_message", "Pin must be numeric"); - return false; - } + // ensure pin is 4 digits + if (pin.size() != 4) { + tree.put("root.paired", 0); + tree.put("root..status_code", 400); + tree.put( + "root..status_message", + std::format("Pin must be 4 digits, {} provided", pin.size()) + ); + BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected reason=pin length must be 4 digits provided_len="sv << pin.size() + << " active_sessions_after="sv << map_id_sess.size(); + return false; + } - auto &sess = std::begin(map_id_sess)->second; - getservercert(sess, tree, pin); - sess.client.name = name; + // ensure all pin characters are numeric + if (!std::all_of(pin.begin(), pin.end(), ::isdigit)) { + tree.put("root.paired", 0); + tree.put("root..status_code", 400); + tree.put("root..status_message", "Pin must be numeric"); + BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected reason=pin must be numeric active_sessions_after="sv << map_id_sess.size(); + return false; + } - // response to the request for pin - std::ostringstream data; - pt::write_xml(data, tree); + auto sess_it = std::begin(map_id_sess); + auto &sess = sess_it->second; + const auto session_key = sess.client.uniqueID; + const auto phase_before = sess.last_phase; + BOOST_LOG(info) << "PAIR_DIAG /api/pin matched session session_key="sv << diag_value(session_key) + << " phase_before="sv << pair_phase_name(phase_before) + << " client_name_before="sv << diag_value(sess.client.name) + << " map_id_sess size before /api/pin getservercert="sv << map_id_sess.size(); + + if (phase_before != PAIR_PHASE::NONE) { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin will call getservercert with bad phase session_key="sv << diag_value(session_key) + << " phase_before="sv << pair_phase_name(phase_before); + } - auto &async_response = sess.async_insert_pin.response; - if (async_response.has_left() && async_response.left()) { - async_response.left()->write(data.str()); - } else if (async_response.has_right() && async_response.right()) { - async_response.right()->write(data.str()); - } else { + getservercert(sess, tree, pin); + + BOOST_LOG(info) << "PAIR_DIAG map_id_sess size after /api/pin getservercert="sv << map_id_sess.size() + << " session_key="sv << diag_value(session_key); + + sess_it = map_id_sess.find(session_key); + if (sess_it == std::end(map_id_sess)) { + const auto status_msg = tree.get("root..status_message", "session removed during getservercert"); + BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected reason=session removed during getservercert" + << " session_key="sv << diag_value(session_key) + << " status_message="sv << status_msg + << " active_sessions_after="sv << map_id_sess.size(); + return false; + } + + sess_it->second.client.name = name; + + const auto paired = tree.get("root.paired", 0); + const auto status_msg = tree.get("root..status_message", ""); + if (paired == 1) { + BOOST_LOG(info) << "PAIR_DIAG /api/pin accepted for getservercert session_key="sv << diag_value(session_key) + << " client_name="sv << diag_value(name) + << " phase_after="sv << pair_phase_name(sess_it->second.last_phase) + << " note=wrong PIN will surface during later challenge verification"; + } else { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected by getservercert session_key="sv << diag_value(session_key) + << " status_message="sv << diag_value(status_msg) + << " phase_after="sv << pair_phase_name(sess_it->second.last_phase); + } + + // response to the request for pin + std::ostringstream data; + pt::write_xml(data, tree); + + auto &async_response = sess_it->second.async_insert_pin.response; + if (async_response.has_left() && async_response.left()) { + async_response.left()->write(data.str()); + } else if (async_response.has_right() && async_response.right()) { + async_response.right()->write(data.str()); + } else { + BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected reason=missing stored async getservercert response" + << " session_key="sv << diag_value(session_key) + << " active_sessions_after="sv << map_id_sess.size(); + return false; + } + + // reset async_response + async_response = std::decay_t(); + BOOST_LOG(info) << "PAIR_DIAG /api/pin complete session_key="sv << diag_value(session_key) + << " active_sessions_before="sv << sessions_before + << " active_sessions_after="sv << map_id_sess.size(); + // response to the current request + return true; + } catch (std::exception &e) { + BOOST_LOG(error) << "PAIR_DIAG exception in /api/pin: "sv << e.what() + << " active_sessions="sv << map_id_sess.size(); + return false; + } catch (...) { + BOOST_LOG(error) << "PAIR_DIAG unknown exception in /api/pin active_sessions="sv << map_id_sess.size(); return false; } - - // reset async_response - async_response = std::decay_t(); - // response to the current request - return true; } template From d3f934542d35c63de864b35f1ae7fb82a311eed6 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 16:45:16 -0400 Subject: [PATCH 02/21] Fix pairing async response diagnostics --- src/nvhttp.cpp | 53 +++++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 50 insertions(+), 3 deletions(-) diff --git a/src/nvhttp.cpp b/src/nvhttp.cpp index 7d118db989b..4872b15db59 100644 --- a/src/nvhttp.cpp +++ b/src/nvhttp.cpp @@ -190,6 +190,23 @@ namespace nvhttp { << " active_sessions="sv << map_id_sess.size(); } + void log_pair_async_response_state(std::string_view marker, const pair_session_t &sess) { + const auto &async_response = sess.async_insert_pin.response; + const auto has_http_variant = async_response.has_left(); + const auto has_https_variant = async_response.has_right(); + const auto http_pointer_present = has_http_variant && static_cast(async_response.left()); + const auto https_pointer_present = has_https_variant && static_cast(async_response.right()); + const auto variant = has_http_variant ? "HTTP"sv : has_https_variant ? "HTTPS"sv : "none"sv; + + BOOST_LOG(info) << "PAIR_DIAG "sv << marker + << " session_key="sv << diag_value(sess.client.uniqueID) + << " response_variant="sv << variant + << " has_http_variant="sv << has_http_variant + << " http_pointer_present="sv << http_pointer_present + << " has_https_variant="sv << has_https_variant + << " https_pointer_present="sv << https_pointer_present; + } + enum class op_e { ADD, ///< Add certificate REMOVE ///< Remove certificate @@ -783,10 +800,13 @@ namespace nvhttp { system_tray::update_tray_require_pin(); #endif ptr->second.async_insert_pin.response = std::move(response); + log_pair_async_response_state("stored getservercert async response", ptr->second); BOOST_LOG(info) << "PAIR_DIAG getservercert waiting for /api/pin session_key="sv << diag_value(session_key) << " active_sessions="sv << map_id_sess.size() - << " async_response_stored=1"; + << " async_response_stored="sv + << ((ptr->second.async_insert_pin.response.has_left() && ptr->second.async_insert_pin.response.left()) || + (ptr->second.async_insert_pin.response.has_right() && ptr->second.async_insert_pin.response.right())); fg.disable(); return; } @@ -934,21 +954,48 @@ namespace nvhttp { // response to the request for pin std::ostringstream data; pt::write_xml(data, tree); + const auto response_body = data.str(); auto &async_response = sess_it->second.async_insert_pin.response; + log_pair_async_response_state("/api/pin stored response before write", sess_it->second); if (async_response.has_left() && async_response.left()) { - async_response.left()->write(data.str()); + BOOST_LOG(info) << "PAIR_DIAG /api/pin writing getservercert XML response" + << " session_key="sv << diag_value(session_key) + << " response_variant=HTTP" + << " response_pointer_present=1" + << " bytes="sv << response_body.size(); + async_response.left()->close_connection_after_response = true; + async_response.left()->write(response_body); + BOOST_LOG(info) << "PAIR_DIAG /api/pin write succeeded" + << " session_key="sv << diag_value(session_key) + << " response_variant=HTTP" + << " active_sessions_after_write="sv << map_id_sess.size(); } else if (async_response.has_right() && async_response.right()) { - async_response.right()->write(data.str()); + BOOST_LOG(info) << "PAIR_DIAG /api/pin writing getservercert XML response" + << " session_key="sv << diag_value(session_key) + << " response_variant=HTTPS" + << " response_pointer_present=1" + << " bytes="sv << response_body.size(); + async_response.right()->close_connection_after_response = true; + async_response.right()->write(response_body); + BOOST_LOG(info) << "PAIR_DIAG /api/pin write succeeded" + << " session_key="sv << diag_value(session_key) + << " response_variant=HTTPS" + << " active_sessions_after_write="sv << map_id_sess.size(); } else { BOOST_LOG(warning) << "PAIR_DIAG /api/pin rejected reason=missing stored async getservercert response" << " session_key="sv << diag_value(session_key) + << " has_http_variant="sv << async_response.has_left() + << " http_pointer_present="sv << (async_response.has_left() && static_cast(async_response.left())) + << " has_https_variant="sv << async_response.has_right() + << " https_pointer_present="sv << (async_response.has_right() && static_cast(async_response.right())) << " active_sessions_after="sv << map_id_sess.size(); return false; } // reset async_response async_response = std::decay_t(); + log_pair_async_response_state("/api/pin stored response after reset", sess_it->second); BOOST_LOG(info) << "PAIR_DIAG /api/pin complete session_key="sv << diag_value(session_key) << " active_sessions_before="sv << sessions_before << " active_sessions_after="sv << map_id_sess.size(); From 94338684d94884f0e767cc426b7547387f69ff34 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 16:54:24 -0400 Subject: [PATCH 03/21] Store pairing async response before session publish --- src/nvhttp.cpp | 24 +++++++++++++++++++----- 1 file changed, 19 insertions(+), 5 deletions(-) diff --git a/src/nvhttp.cpp b/src/nvhttp.cpp index 4872b15db59..bbffdab1b1c 100644 --- a/src/nvhttp.cpp +++ b/src/nvhttp.cpp @@ -761,10 +761,17 @@ namespace nvhttp { sess.client.uniqueID = std::move(uniqID); sess.client.cert = util::from_hex_vec(get_arg(args, "clientcert"), true); + sess.async_insert_pin.salt = get_arg(args, "salt"); const auto session_key = sess.client.uniqueID; const auto client_cert_len = sess.client.cert.size(); const auto sessions_before = map_id_sess.size(); + const auto async_pin = !config::sunshine.flags[config::flag::PIN_STDIN]; + if (async_pin) { + sess.async_insert_pin.response = std::move(response); + log_pair_async_response_state("prepared getservercert async response before session insert", sess); + } + BOOST_LOG(info) << "PAIR_DIAG creating pairing session session_key="sv << diag_value(session_key) << " client_cert_len="sv << client_cert_len << " devicename="sv << diag_value(devicename_arg) @@ -773,7 +780,13 @@ namespace nvhttp { << " active_sessions_before="sv << sessions_before; BOOST_LOG(debug) << sess.client.cert; - auto [ptr, inserted] = map_id_sess.emplace(sess.client.uniqueID, std::move(sess)); + auto [ptr, inserted] = map_id_sess.try_emplace(session_key, std::move(sess)); + if (!inserted) { + ptr->second.async_insert_pin.salt = get_arg(args, "salt"); + if (async_pin) { + ptr->second.async_insert_pin.response = std::move(sess.async_insert_pin.response); + } + } BOOST_LOG(info) << "PAIR_DIAG pairing session created session_key="sv << diag_value(session_key) << " inserted="sv << inserted @@ -781,7 +794,11 @@ namespace nvhttp { << " active_sessions_after="sv << map_id_sess.size() << " stored_phase="sv << pair_phase_name(ptr->second.last_phase); - ptr->second.async_insert_pin.salt = std::move(get_arg(args, "salt")); + if (async_pin) { + fg.disable(); + log_pair_async_response_state("stored getservercert async response immediately after session insert", ptr->second); + } + log_pair_session_marker("getservercert session ready for PIN", ptr->second); if (config::sunshine.flags[config::flag::PIN_STDIN]) { std::string pin; @@ -799,15 +816,12 @@ namespace nvhttp { #if defined SUNSHINE_TRAY && SUNSHINE_TRAY >= 1 system_tray::update_tray_require_pin(); #endif - ptr->second.async_insert_pin.response = std::move(response); - log_pair_async_response_state("stored getservercert async response", ptr->second); BOOST_LOG(info) << "PAIR_DIAG getservercert waiting for /api/pin session_key="sv << diag_value(session_key) << " active_sessions="sv << map_id_sess.size() << " async_response_stored="sv << ((ptr->second.async_insert_pin.response.has_left() && ptr->second.async_insert_pin.response.left()) || (ptr->second.async_insert_pin.response.has_right() && ptr->second.async_insert_pin.response.right())); - fg.disable(); return; } } else if (it->second == "pairchallenge"sv) { From 86c6867d8fbc9a0573eea2d00e2639293d8c23a0 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 18:30:03 -0400 Subject: [PATCH 04/21] Add stream startup diagnostics --- src/rtsp.cpp | 80 +++++++++++++ src/stream.cpp | 303 +++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 383 insertions(+) diff --git a/src/rtsp.cpp b/src/rtsp.cpp index 4dd8b12c8e0..9ef64b15f51 100644 --- a/src/rtsp.cpp +++ b/src/rtsp.cpp @@ -14,6 +14,7 @@ extern "C" { #include #include #include +#include #include #include @@ -86,6 +87,50 @@ namespace rtsp_stream { void cmd_not_found(tcp::socket &sock, launch_session_t &, msg_t &&req); void respond(tcp::socket &sock, launch_session_t &session, POPTION_ITEM options, int statuscode, const char *status_msg, int seqn, const std::string_view &payload); + std::string rtsp_option_value(PRTSP_MESSAGE msg, std::string_view name) { + for (auto option = msg->options; option != nullptr; option = option->next) { + std::string_view option_name {option->option ? option->option : ""}; + if (name == option_name) { + return option->content ? std::string(option->content) : std::string {}; + } + } + + return {}; + } + + std::string rtsp_message_to_string(PRTSP_MESSAGE msg) { + std::ostringstream ss; + + if (msg->type == TYPE_RESPONSE) { + ss << msg->protocol << ' ' << msg->message.response.statusCode << ' ' << msg->message.response.statusString << "\r\n"; + } else { + ss << msg->message.request.command << ' ' << msg->message.request.target << ' ' << msg->protocol << "\r\n"; + } + + for (auto option = msg->options; option != nullptr; option = option->next) { + ss << option->option << ": " << (option->content ? option->content : "") << "\r\n"; + } + + ss << "\r\n"; + if (msg->payload && msg->payloadLength > 0) { + ss << std::string_view {msg->payload, static_cast(msg->payloadLength)}; + } + + return ss.str(); + } + + std::string rtsp_response_to_string(int statuscode, const char *status_msg, POPTION_ITEM options, const std::string_view &payload) { + std::ostringstream ss; + + ss << "RTSP/1.0 " << statuscode << ' ' << status_msg << "\r\n"; + for (auto option = options; option != nullptr; option = option->next) { + ss << option->option << ": " << (option->content ? option->content : "") << "\r\n"; + } + + ss << "\r\n" << payload; + return ss.str(); + } + class socket_t: public std::enable_shared_from_this { public: socket_t(boost::asio::io_context &io_context, std::function &&handle_data_fn): @@ -850,6 +895,21 @@ namespace rtsp_stream { auto begin = std::find(std::begin(target), std::end(target), '=') + 1; auto end = std::find(begin, std::end(target), '/'); std::string_view type {begin, (size_t) std::distance(begin, end)}; + std::string_view stream_id {begin, static_cast(std::distance(begin, std::end(target)))}; + const auto client_port = rtsp_option_value(req.get(), "X-GS-ClientPort"sv); + const auto transport = rtsp_option_value(req.get(), "Transport"sv); + + BOOST_LOG(info) << "STREAM_DIAG RTSP SETUP request" + << " session_id="sv << session.id + << " channel="sv << type + << " stream_id="sv << stream_id + << " target="sv << target + << " x_gs_client_port="sv << (client_port.empty() ? ""s : client_port) + << " transport="sv << (transport.empty() ? ""s : transport) + << std::endl + << "---BEGIN STREAM_DIAG RTSP SETUP REQUEST---"sv << std::endl + << rtsp_message_to_string(req.get()) + << "---END STREAM_DIAG RTSP SETUP REQUEST---"sv; std::uint16_t port; if (type == "audio"sv) { @@ -889,6 +949,26 @@ namespace rtsp_stream { port_option.next = &payload_option; + BOOST_LOG(info) << "STREAM_DIAG RTSP SETUP parsed" + << " session_id="sv << session.id + << " channel="sv << type + << " stream_id="sv << stream_id + << " server_udp_port="sv << port + << " x_gs_client_port="sv << (client_port.empty() ? ""s : client_port) + << " payload_option="sv << payload_option.option + << " payload_value="sv << payload_option.content; + + BOOST_LOG(info) << "STREAM_DIAG RTSP SETUP response" + << " session_id="sv << session.id + << " channel="sv << type + << " stream_id="sv << stream_id + << " server_udp_port="sv << port + << " x_gs_client_port="sv << (client_port.empty() ? ""s : client_port) + << std::endl + << "---BEGIN STREAM_DIAG RTSP SETUP RESPONSE---"sv << std::endl + << rtsp_response_to_string(200, "OK", &seqn, {}) + << "---END STREAM_DIAG RTSP SETUP RESPONSE---"sv; + respond(sock, session, &seqn, 200, "OK", req->sequenceNumber, {}); } diff --git a/src/stream.cpp b/src/stream.cpp index 8b303ef24da..38979986dd7 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -4,9 +4,11 @@ */ // standard includes +#include #include #include #include +#include // lib includes #include @@ -84,6 +86,27 @@ namespace stream { audio ///< Audio }; + std::string_view stream_diag_channel_name(socket_e type) { + switch (type) { + case socket_e::video: + return "VIDEO"sv; + case socket_e::audio: + return "AUDIO"sv; + } + + return "UNKNOWN"sv; + } + + std::uint16_t stream_diag_local_udp_port(udp::socket &sock) { + boost::system::error_code ec; + auto endpoint = sock.local_endpoint(ec); + if (ec) { + return 0; + } + + return endpoint.port(); + } + #pragma pack(push, 1) struct video_short_frame_header_t { @@ -245,6 +268,14 @@ namespace stream { using message_queue_t = std::shared_ptr>>; using message_queue_queue_t = std::shared_ptr>>; + std::string stream_diag_av_session_id(const av_session_id_t &session_id) { + if (std::holds_alternative(session_id)) { + return std::get(session_id).to_string(); + } + + return util::hex_vec(std::get(session_id)); + } + // return bytes written on success // return -1 on error static inline int encode_audio(bool encrypted, const audio::buffer_t &plaintext, uint8_t *destination, crypto::aes_t &iv, crypto::cipher::cbc_t &cbc) { @@ -266,7 +297,10 @@ namespace stream { class control_server_t { public: int bind(net::af_e address_family, std::uint16_t port) { + BOOST_LOG(info) << "STREAM_DIAG udp bind begin channel=CONTROL local_port="sv << port; _host = net::host_create(address_family, _addr, port); + BOOST_LOG(info) << "STREAM_DIAG udp bind "sv << (_host ? "success"sv : "failed"sv) + << " channel=CONTROL local_port="sv << port; return !(bool) _host; } @@ -300,10 +334,29 @@ namespace stream { auto packet = enet_packet_create(payload.data(), payload.size(), ENET_PACKET_FLAG_RELIABLE); if (enet_peer_send(peer, 0, packet)) { enet_packet_destroy(packet); + TUPLE_2D(port, addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); + BOOST_LOG(warning) << "STREAM_DIAG udp send failed channel=CONTROL" + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << addr << ':' << port + << " bytes="sv << payload.size(); return -1; } + TUPLE_2D(port, addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); + std::uint64_t total_packets_sent = 0; + { + auto lg = _peer_to_session.lock(); + auto it = _peer_to_session->find(peer); + if (it != _peer_to_session->end()) { + total_packets_sent = it->second->stream_diag.control_udp_sent.fetch_add(1) + 1; + } + } + BOOST_LOG(info) << "STREAM_DIAG udp send queued channel=CONTROL" + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << addr << ':' << port + << " bytes="sv << payload.size() + << " total_packets_sent="sv << total_packets_sent; return 0; } @@ -406,12 +459,42 @@ namespace stream { std::uint32_t launch_session_id; + struct { + std::atomic_bool video_ping_ready {false}; + std::atomic_bool audio_ping_ready {false}; + std::atomic_bool control_peer_ready {false}; + + std::atomic_uint64_t video_udp_received {0}; + std::atomic_uint64_t audio_udp_received {0}; + std::atomic_uint64_t control_udp_received {0}; + + std::atomic_uint64_t video_udp_sent {0}; + std::atomic_uint64_t audio_udp_sent {0}; + std::atomic_uint64_t control_udp_sent {0}; + } stream_diag; + safe::mail_raw_t::event_t shutdown_event; safe::signal_t controlEnd; std::atomic state; }; + void stream_diag_log_ready_state(std::string_view marker, session_t *session, std::string_view channel) { + BOOST_LOG(info) << "STREAM_DIAG "sv << marker + << " channel="sv << channel + << " launch_session_id="sv << session->launch_session_id + << " video_ping_ready="sv << session->stream_diag.video_ping_ready.load() + << " audio_ping_ready="sv << session->stream_diag.audio_ping_ready.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " video_udp_received="sv << session->stream_diag.video_udp_received.load() + << " audio_udp_received="sv << session->stream_diag.audio_udp_received.load() + << " control_udp_received="sv << session->stream_diag.control_udp_received.load() + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_udp_sent="sv << session->stream_diag.audio_udp_sent.load() + << " control_udp_sent="sv << session->stream_diag.control_udp_sent.load() + << " audio_raised_alone_blocks_video_or_control=0"; + } + /** * First part of cipher must be struct of type control_encrypted_t * @@ -515,6 +598,7 @@ namespace stream { rtsp_stream::launch_session_clear(session_p->launch_session_id); session_p->control.peer = peer; + session_p->stream_diag.control_peer_ready.store(true); // Use the local address from the control connection as the source address // for other communications to the client. This is necessary to ensure @@ -529,6 +613,13 @@ namespace stream { BOOST_LOG(debug) << "Control local address ["sv << local_address << ']'; BOOST_LOG(debug) << "Control peer address ["sv << peer_addr << ':' << peer_port << ']'; + BOOST_LOG(info) << "STREAM_DIAG control peer ready" + << " launch_session_id="sv << session_p->launch_session_id + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << peer_addr << ':' << peer_port + << " connect_data="sv << connect_data + << " expected_peer_address="sv << session_p->control.expected_peer_address; + stream_diag_log_ready_state("ready state after control peer", session_p, "CONTROL"sv); // Insert this into the map for O(1) lookups in the future auto ptslg = _peer_to_session.lock(); @@ -570,6 +661,30 @@ namespace stream { auto res = enet_host_service(_host.get(), &event, (enet_uint32) timeout.count()); if (res > 0) { + TUPLE_2D(event_port, event_addr, platf::from_sockaddr_ex((sockaddr *) &event.peer->address.address)); + const char *event_type = "UNKNOWN"; + switch (event.type) { + case ENET_EVENT_TYPE_CONNECT: + event_type = "CONNECT"; + break; + case ENET_EVENT_TYPE_DISCONNECT: + event_type = "DISCONNECT"; + break; + case ENET_EVENT_TYPE_RECEIVE: + event_type = "RECEIVE"; + break; + case ENET_EVENT_TYPE_NONE: + event_type = "NONE"; + break; + } + BOOST_LOG(info) << "STREAM_DIAG udp receive" + << " channel=CONTROL" + << " event="sv << event_type + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << event_addr << ':' << event_port + << " bytes="sv << (event.packet ? event.packet->dataLength : 0) + << " connect_data="sv << event.data; + auto session = get_session(event.peer, event.data); if (!session) { BOOST_LOG(warning) << "Rejected connection from ["sv << platf::from_sockaddr((sockaddr *) &event.peer->address.address) << "]: it's not properly set up"sv; @@ -577,6 +692,9 @@ namespace stream { return; } + if (event.type == ENET_EVENT_TYPE_RECEIVE) { + session->stream_diag.control_udp_received.fetch_add(1); + } session->pingTimeout = std::chrono::steady_clock::now() + config::stream.ping_timeout; @@ -1086,6 +1204,14 @@ namespace stream { if (now > session->pingTimeout) { auto address = session->control.peer ? platf::from_sockaddr((sockaddr *) &session->control.peer->address.address) : session->control.expected_peer_address; + BOOST_LOG(error) << "STREAM_DIAG control ping timeout" + << " channel=CONTROL" + << " launch_session_id="sv << session->launch_session_id + << " wait_condition=no control ENet activity before session pingTimeout" + << " remote="sv << address + << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() + << " audio_raised_alone_blocks_video_or_control=0"; + stream_diag_log_ready_state("ready state at control ping timeout", session, "CONTROL"sv); BOOST_LOG(info) << address << ": Ping Timeout"sv; session::stop(*session); } @@ -1201,15 +1327,23 @@ namespace stream { case socket_e::video: if (message_queue) { peer_to_video_session.emplace(session_id, message_queue); + BOOST_LOG(info) << "STREAM_DIAG udp route register" + << " channel=VIDEO key="sv << stream_diag_av_session_id(session_id); } else { peer_to_video_session.erase(session_id); + BOOST_LOG(info) << "STREAM_DIAG udp route unregister" + << " channel=VIDEO key="sv << stream_diag_av_session_id(session_id); } break; case socket_e::audio: if (message_queue) { peer_to_audio_session.emplace(session_id, message_queue); + BOOST_LOG(info) << "STREAM_DIAG udp route register" + << " channel=AUDIO key="sv << stream_diag_av_session_id(session_id); } else { peer_to_audio_session.erase(session_id); + BOOST_LOG(info) << "STREAM_DIAG udp route unregister" + << " channel=AUDIO key="sv << stream_diag_av_session_id(session_id); } break; } @@ -1224,6 +1358,12 @@ namespace stream { auto type_str = buf_elem ? "AUDIO"sv : "VIDEO"sv; BOOST_LOG(verbose) << "Recv: "sv << peer.address().to_string() << ':' << peer.port() << " :: " << type_str; + BOOST_LOG(info) << "STREAM_DIAG udp receive" + << " channel="sv << type_str + << " local_port="sv << stream_diag_local_udp_port(sock) + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " bytes="sv << bytes + << " ec="sv << ec.message(); populate_peer_to_session(); @@ -1242,7 +1382,20 @@ namespace stream { auto it = peer_to_session.find(peer.address()); if (it != std::end(peer_to_session)) { BOOST_LOG(debug) << "RAISE: "sv << peer.address().to_string() << ':' << peer.port() << " :: " << type_str; + BOOST_LOG(info) << "STREAM_DIAG udp packet matched" + << " channel="sv << type_str + << " match=legacy-address" + << " local_port="sv << stream_diag_local_udp_port(sock) + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " bytes="sv << bytes; it->second->raise(peer, std::string {buf[buf_elem].data(), bytes}); + } else { + BOOST_LOG(warning) << "STREAM_DIAG udp packet unmatched" + << " channel="sv << type_str + << " match=legacy-address" + << " local_port="sv << stream_diag_local_udp_port(sock) + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " bytes="sv << bytes; } } else if (bytes >= sizeof(SS_PING)) { auto ping = (PSS_PING) buf[buf_elem].data(); @@ -1251,8 +1404,29 @@ namespace stream { auto it = peer_to_session.find(std::string {ping->payload, sizeof(ping->payload)}); if (it != std::end(peer_to_session)) { BOOST_LOG(debug) << "RAISE: "sv << peer.address().to_string() << ':' << peer.port() << " :: " << type_str; + BOOST_LOG(info) << "STREAM_DIAG udp packet matched" + << " channel="sv << type_str + << " match=session-payload" + << " local_port="sv << stream_diag_local_udp_port(sock) + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " bytes="sv << bytes + << " payload="sv << util::hex_vec(std::string_view {ping->payload, sizeof(ping->payload)}); it->second->raise(peer, std::string {buf[buf_elem].data(), bytes}); + } else { + BOOST_LOG(warning) << "STREAM_DIAG udp packet unmatched" + << " channel="sv << type_str + << " match=session-payload" + << " local_port="sv << stream_diag_local_udp_port(sock) + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " bytes="sv << bytes + << " payload="sv << util::hex_vec(std::string_view {ping->payload, sizeof(ping->payload)}); } + } else { + BOOST_LOG(warning) << "STREAM_DIAG udp packet unclassified" + << " channel="sv << type_str + << " local_port="sv << stream_diag_local_udp_port(sock) + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " bytes="sv << bytes; } }; }; @@ -1538,6 +1712,7 @@ namespace stream { batch_info.block_count = current_batch_size; frame_send_batch_latency_logger.first_point_now(); + const auto packets_in_batch = current_batch_size; // Use a batched send if it's supported on this platform if (!platf::send_batch(batch_info)) { // Batched send is not available, so send each packet individually @@ -1557,6 +1732,19 @@ namespace stream { platf::send(send_info); } } + const auto video_sent_count = session->stream_diag.video_udp_sent.fetch_add(packets_in_batch) + packets_in_batch; + if (video_sent_count <= 5 || video_sent_count % 300 == 0) { + BOOST_LOG(info) << "STREAM_DIAG udp send" + << " channel=VIDEO" + << " local_port="sv << net::map_port(VIDEO_STREAM_PORT) + << " remote="sv << peer_address.to_string() << ':' << session->video.peer.port() + << " packets_in_batch="sv << packets_in_batch + << " bytes_approx="sv << (packets_in_batch * blocksize) + << " total_packets_sent="sv << video_sent_count + << " audio_ping_ready="sv << session->stream_diag.audio_ping_ready.load() + << " video_ping_ready="sv << session->stream_diag.video_ping_ready.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load(); + } frame_send_batch_latency_logger.second_point_now_and_log(); ratecontrol_group_packets_sent += current_batch_size; @@ -1658,6 +1846,18 @@ namespace stream { session->localAddress, }; platf::send(send_info); + const auto audio_sent_count = session->stream_diag.audio_udp_sent.fetch_add(1) + 1; + if (audio_sent_count <= 5 || audio_sent_count % 300 == 0) { + BOOST_LOG(info) << "STREAM_DIAG udp send" + << " channel=AUDIO" + << " local_port="sv << net::map_port(AUDIO_STREAM_PORT) + << " remote="sv << peer_address.to_string() << ':' << session->audio.peer.port() + << " bytes_approx="sv << (sizeof(audio_packet) + static_cast(bytes)) + << " total_packets_sent="sv << audio_sent_count + << " audio_ping_ready="sv << session->stream_diag.audio_ping_ready.load() + << " video_ping_ready="sv << session->stream_diag.video_ping_ready.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load(); + } auto &fec_packet = session->audio.fec_packet; // initialize the FEC header at the beginning of the FEC block @@ -1685,6 +1885,19 @@ namespace stream { session->localAddress, }; platf::send(send_info); + const auto audio_fec_sent_count = session->stream_diag.audio_udp_sent.fetch_add(1) + 1; + if (audio_fec_sent_count <= 5 || audio_fec_sent_count % 300 == 0) { + BOOST_LOG(info) << "STREAM_DIAG udp send" + << " channel=AUDIO" + << " subtype=FEC" + << " local_port="sv << net::map_port(AUDIO_STREAM_PORT) + << " remote="sv << peer_address.to_string() << ':' << session->audio.peer.port() + << " bytes_approx="sv << (sizeof(fec_packet) + static_cast(bytes)) + << " total_packets_sent="sv << audio_fec_sent_count + << " audio_ping_ready="sv << session->stream_diag.audio_ping_ready.load() + << " video_ping_ready="sv << session->stream_diag.video_ping_ready.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load(); + } BOOST_LOG(verbose) << "Audio FEC ["sv << (sequenceNumber & ~(RTPA_DATA_SHARDS - 1)) << ' ' << x << "] :: send..."sv; } } @@ -1705,18 +1918,22 @@ namespace stream { auto audio_port = net::map_port(AUDIO_STREAM_PORT); if (ctx.control_server.bind(address_family, control_port)) { + BOOST_LOG(error) << "STREAM_DIAG udp bind failed channel=CONTROL local_port="sv << control_port; BOOST_LOG(error) << "Couldn't bind Control server to port ["sv << control_port << "], likely another process already bound to the port"sv; return -1; } boost::system::error_code ec; + BOOST_LOG(info) << "STREAM_DIAG udp open begin channel=VIDEO local_port="sv << video_port; ctx.video_sock.open(protocol, ec); if (ec) { + BOOST_LOG(fatal) << "STREAM_DIAG udp open failed channel=VIDEO local_port="sv << video_port << " error="sv << ec.message(); BOOST_LOG(fatal) << "Couldn't open socket for Video server: "sv << ec.message(); return -1; } + BOOST_LOG(info) << "STREAM_DIAG udp open success channel=VIDEO local_port="sv << video_port; // Set video socket send buffer size (SO_SENDBUF) to 1MB try { @@ -1732,26 +1949,35 @@ namespace stream { return -1; } + BOOST_LOG(info) << "STREAM_DIAG udp bind begin channel=VIDEO bind_addr="sv << bind_addr_str << " local_port="sv << video_port; ctx.video_sock.bind(udp::endpoint(bind_addr, video_port), ec); if (ec) { + BOOST_LOG(fatal) << "STREAM_DIAG udp bind failed channel=VIDEO bind_addr="sv << bind_addr_str << " local_port="sv << video_port << " error="sv << ec.message(); BOOST_LOG(fatal) << "Couldn't bind Video server to port ["sv << video_port << "]: "sv << ec.message(); return -1; } + BOOST_LOG(info) << "STREAM_DIAG udp bind success channel=VIDEO bind_addr="sv << bind_addr_str << " local_port="sv << video_port; + BOOST_LOG(info) << "STREAM_DIAG udp open begin channel=AUDIO local_port="sv << audio_port; ctx.audio_sock.open(protocol, ec); if (ec) { + BOOST_LOG(fatal) << "STREAM_DIAG udp open failed channel=AUDIO local_port="sv << audio_port << " error="sv << ec.message(); BOOST_LOG(fatal) << "Couldn't open socket for Audio server: "sv << ec.message(); return -1; } + BOOST_LOG(info) << "STREAM_DIAG udp open success channel=AUDIO local_port="sv << audio_port; + BOOST_LOG(info) << "STREAM_DIAG udp bind begin channel=AUDIO bind_addr="sv << bind_addr_str << " local_port="sv << audio_port; ctx.audio_sock.bind(udp::endpoint(bind_addr, audio_port), ec); if (ec) { + BOOST_LOG(fatal) << "STREAM_DIAG udp bind failed channel=AUDIO bind_addr="sv << bind_addr_str << " local_port="sv << audio_port << " error="sv << ec.message(); BOOST_LOG(fatal) << "Couldn't bind Audio server to port ["sv << audio_port << "]: "sv << ec.message(); return -1; } + BOOST_LOG(info) << "STREAM_DIAG udp bind success channel=AUDIO bind_addr="sv << bind_addr_str << " local_port="sv << audio_port; ctx.message_queue_queue = std::make_shared(30); @@ -1801,6 +2027,7 @@ namespace stream { int recv_ping(session_t *session, decltype(broadcast)::ptr_t ref, socket_e type, std::string_view expected_payload, udp::endpoint &peer, std::chrono::milliseconds timeout) { auto messages = std::make_shared(30); av_session_id_t session_id = std::string {expected_payload}; + const auto channel = stream_diag_channel_name(type); // Only allow matches on the peer address for legacy clients if (!(session->config.mlFeatureFlags & ML_FF_SESSION_ID_V1)) { @@ -1808,6 +2035,16 @@ namespace stream { } ref->message_queue_queue->raise(type, session_id, messages); + BOOST_LOG(info) << "STREAM_DIAG initial ping wait begin" + << " channel="sv << channel + << " launch_session_id="sv << session->launch_session_id + << " expected_payload="sv << util::hex_vec(expected_payload) + << " initial_peer="sv << peer.address().to_string() << ':' << peer.port() + << " timeout_ms="sv << timeout.count() + << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() + << " ml_session_id_v1="sv << static_cast(session->config.mlFeatureFlags & ML_FF_SESSION_ID_V1); + stream_diag_log_ready_state("ready state before initial ping wait", session, channel); + auto fg = util::fail_guard([&]() { messages->stop(); @@ -1830,6 +2067,20 @@ namespace stream { } TUPLE_2D_REF(recv_peer, msg, *msg_opt); + if (type == socket_e::video) { + session->stream_diag.video_udp_received.fetch_add(1); + } else { + session->stream_diag.audio_udp_received.fetch_add(1); + } + + BOOST_LOG(info) << "STREAM_DIAG initial ping candidate" + << " channel="sv << channel + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << recv_peer.address().to_string() << ':' << recv_peer.port() + << " bytes="sv << msg.size() + << " expected_payload="sv << util::hex_vec(expected_payload) + << " payload="sv << util::hex_vec(msg); + if (msg.find(expected_payload) != std::string::npos) { // Match the new PING payload format BOOST_LOG(debug) << "Received ping [v2] from "sv << recv_peer.address() << ':' << recv_peer.port() << " ["sv << util::hex_vec(msg) << ']'; @@ -1844,9 +2095,32 @@ namespace stream { // Update connection details. peer = recv_peer; + if (type == socket_e::video) { + session->stream_diag.video_ping_ready.store(true); + } else { + session->stream_diag.audio_ping_ready.store(true); + } + + BOOST_LOG(info) << "STREAM_DIAG initial ping accepted" + << " channel="sv << channel + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << peer.address().to_string() << ':' << peer.port() + << " audio_raised_alone_blocks_video_or_control=0"; + stream_diag_log_ready_state("ready state after initial ping", session, channel); return 0; } + const auto elapsed = std::chrono::duration_cast(std::chrono::steady_clock::now() - start_time); + BOOST_LOG(error) << "STREAM_DIAG initial ping timeout" + << " channel="sv << channel + << " launch_session_id="sv << session->launch_session_id + << " wait_condition=no matching ping before configured ping_timeout" + << " elapsed_ms="sv << elapsed.count() + << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() + << " expected_payload="sv << util::hex_vec(expected_payload) + << " last_peer="sv << peer.address().to_string() << ':' << peer.port() + << " audio_raised_alone_blocks_video_or_control=0"; + stream_diag_log_ready_state("ready state at initial ping timeout", session, channel); BOOST_LOG(error) << "Initial Ping Timeout"sv; return -1; } @@ -1859,6 +2133,10 @@ namespace stream { while_starting_do_nothing(session->state); + BOOST_LOG(info) << "STREAM_DIAG video thread waiting for initial ping" + << " launch_session_id="sv << session->launch_session_id + << " expected_payload="sv << util::hex_vec(session->video.ping_payload) + << " timeout_ms="sv << config::stream.ping_timeout.count(); auto ref = broadcast.ref(); auto error = recv_ping(session, ref, socket_e::video, session->video.ping_payload, session->video.peer, config::stream.ping_timeout); if (error < 0) { @@ -1870,6 +2148,9 @@ namespace stream { session->video.qos = platf::enable_socket_qos(ref->video_sock.native_handle(), address, session->video.peer.port(), platf::qos_data_type_e::video, session->config.videoQosType != 0); BOOST_LOG(debug) << "Start capturing Video"sv; + BOOST_LOG(info) << "STREAM_DIAG video channel ready; starting capture" + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << session->video.peer.address().to_string() << ':' << session->video.peer.port(); video::capture(session->mail, session->config.monitor, session); } @@ -1881,6 +2162,11 @@ namespace stream { while_starting_do_nothing(session->state); + BOOST_LOG(info) << "STREAM_DIAG audio thread waiting for initial ping" + << " launch_session_id="sv << session->launch_session_id + << " expected_payload="sv << util::hex_vec(session->audio.ping_payload) + << " timeout_ms="sv << config::stream.ping_timeout.count() + << " audio_raised_alone_blocks_video_or_control=0"; auto ref = broadcast.ref(); auto error = recv_ping(session, ref, socket_e::audio, session->audio.ping_payload, session->audio.peer, config::stream.ping_timeout); if (error < 0) { @@ -1892,6 +2178,10 @@ namespace stream { session->audio.qos = platf::enable_socket_qos(ref->audio_sock.native_handle(), address, session->audio.peer.port(), platf::qos_data_type_e::audio, session->config.audioQosType != 0); BOOST_LOG(debug) << "Start capturing Audio"sv; + BOOST_LOG(info) << "STREAM_DIAG audio channel ready; starting capture" + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << session->audio.peer.address().to_string() << ':' << session->audio.peer.port() + << " audio_raised_alone_blocks_video_or_control=0"; audio::capture(session->mail, session->config.audio, session); } @@ -1970,6 +2260,15 @@ namespace stream { session.control.expected_peer_address = addr_string; BOOST_LOG(debug) << "Expecting incoming session connections from "sv << addr_string; + BOOST_LOG(info) << "STREAM_DIAG stream session start" + << " launch_session_id="sv << session.launch_session_id + << " expected_client_address="sv << addr_string + << " video_udp_port="sv << net::map_port(VIDEO_STREAM_PORT) + << " control_udp_port="sv << net::map_port(CONTROL_PORT) + << " audio_udp_port="sv << net::map_port(AUDIO_STREAM_PORT) + << " ping_timeout_ms="sv << config::stream.ping_timeout.count() + << " audio_and_video_waiters_independent=1" + << " audio_raised_alone_blocks_video_or_control=0"; // Insert this session into the session list { @@ -1988,6 +2287,10 @@ namespace stream { session.audioThread = std::thread {audioThread, &session}; session.videoThread = std::thread {videoThread, &session}; + BOOST_LOG(info) << "STREAM_DIAG stream session channel threads started" + << " launch_session_id="sv << session.launch_session_id + << " audio_thread=1 video_thread=1 control_thread=shared-broadcast" + << " audio_raised_alone_blocks_video_or_control=0"; session.state.store(state_e::RUNNING, std::memory_order_relaxed); From 08f4de4a4eaafc3979d2c28b94be05d16d1bb1e1 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 18:39:07 -0400 Subject: [PATCH 05/21] Fix stream diagnostics build --- src/stream.cpp | 60 ++++++++++++++++++++++++++------------------------ 1 file changed, 31 insertions(+), 29 deletions(-) diff --git a/src/stream.cpp b/src/stream.cpp index 38979986dd7..33abca509f1 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -330,35 +330,7 @@ namespace stream { _map_type_cb.emplace(type, std::move(cb)); } - int send(const std::string_view &payload, net::peer_t peer) { - auto packet = enet_packet_create(payload.data(), payload.size(), ENET_PACKET_FLAG_RELIABLE); - if (enet_peer_send(peer, 0, packet)) { - enet_packet_destroy(packet); - TUPLE_2D(port, addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); - BOOST_LOG(warning) << "STREAM_DIAG udp send failed channel=CONTROL" - << " local_port="sv << net::map_port(CONTROL_PORT) - << " remote="sv << addr << ':' << port - << " bytes="sv << payload.size(); - - return -1; - } - - TUPLE_2D(port, addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); - std::uint64_t total_packets_sent = 0; - { - auto lg = _peer_to_session.lock(); - auto it = _peer_to_session->find(peer); - if (it != _peer_to_session->end()) { - total_packets_sent = it->second->stream_diag.control_udp_sent.fetch_add(1) + 1; - } - } - BOOST_LOG(info) << "STREAM_DIAG udp send queued channel=CONTROL" - << " local_port="sv << net::map_port(CONTROL_PORT) - << " remote="sv << addr << ':' << port - << " bytes="sv << payload.size() - << " total_packets_sent="sv << total_packets_sent; - return 0; - } + int send(const std::string_view &payload, net::peer_t peer); void flush() { enet_host_flush(_host.get()); @@ -557,6 +529,36 @@ namespace stream { static auto broadcast = safe::make_shared(start_broadcast, end_broadcast); + int control_server_t::send(const std::string_view &payload, net::peer_t peer) { + auto packet = enet_packet_create(payload.data(), payload.size(), ENET_PACKET_FLAG_RELIABLE); + if (enet_peer_send(peer, 0, packet)) { + enet_packet_destroy(packet); + TUPLE_2D(port, addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); + BOOST_LOG(warning) << "STREAM_DIAG udp send failed channel=CONTROL" + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << addr << ':' << port + << " bytes="sv << payload.size(); + + return -1; + } + + TUPLE_2D(port, addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); + std::uint64_t total_packets_sent = 0; + { + auto lg = _peer_to_session.lock(); + auto it = _peer_to_session->find(peer); + if (it != _peer_to_session->end()) { + total_packets_sent = it->second->stream_diag.control_udp_sent.fetch_add(1) + 1; + } + } + BOOST_LOG(info) << "STREAM_DIAG udp send queued channel=CONTROL" + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << addr << ':' << port + << " bytes="sv << payload.size() + << " total_packets_sent="sv << total_packets_sent; + return 0; + } + session_t *control_server_t::get_session(const net::peer_t peer, uint32_t connect_data) { { // Fast path - look up existing session by peer From 7695178b572e63fea3006988e424c4e5bde432f9 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 18:50:59 -0400 Subject: [PATCH 06/21] Diagnose RTSP client ports and audio-only UDP path --- src/rtsp.cpp | 126 +++++++++++++++++++++++++++++++++++++++++++++++-- src/rtsp.h | 7 ++- src/stream.cpp | 119 +++++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 245 insertions(+), 7 deletions(-) diff --git a/src/rtsp.cpp b/src/rtsp.cpp index 9ef64b15f51..e853f57100c 100644 --- a/src/rtsp.cpp +++ b/src/rtsp.cpp @@ -12,7 +12,10 @@ extern "C" { // standard includes #include #include +#include #include +#include +#include #include #include #include @@ -98,6 +101,109 @@ namespace rtsp_stream { return {}; } + std::string_view trim_rtsp_token(std::string_view value) { + while (!value.empty() && std::isspace(static_cast(value.front()))) { + value.remove_prefix(1); + } + + while (!value.empty() && std::isspace(static_cast(value.back()))) { + value.remove_suffix(1); + } + + return value; + } + + bool rtsp_token_iequals(std::string_view lhs, std::string_view rhs) { + if (lhs.size() != rhs.size()) { + return false; + } + + for (std::size_t x = 0; x < lhs.size(); ++x) { + if (std::tolower(static_cast(lhs[x])) != std::tolower(static_cast(rhs[x]))) { + return false; + } + } + + return true; + } + + std::string rtsp_transport_param_value(std::string_view transport, std::string_view name) { + while (!transport.empty()) { + auto next = transport.find(';'); + auto token = trim_rtsp_token(next == std::string_view::npos ? transport : transport.substr(0, next)); + + auto equals = token.find('='); + if (equals != std::string_view::npos) { + auto key = trim_rtsp_token(token.substr(0, equals)); + auto value = trim_rtsp_token(token.substr(equals + 1)); + if (rtsp_token_iequals(key, name)) { + return std::string {value}; + } + } + + if (next == std::string_view::npos) { + break; + } + transport.remove_prefix(next + 1); + } + + return {}; + } + + std::optional rtsp_parse_u16(std::string_view value) { + value = trim_rtsp_token(value); + if (value.empty()) { + return std::nullopt; + } + + unsigned int parsed = 0; + auto [ptr, ec] = std::from_chars(value.data(), value.data() + value.size(), parsed); + if (ec != std::errc {} || ptr != value.data() + value.size() || parsed > std::numeric_limits::max()) { + return std::nullopt; + } + + return static_cast(parsed); + } + + struct client_port_info_t { + std::string raw; + std::string source; + std::optional rtp; + std::optional rtcp; + }; + + client_port_info_t rtsp_client_port_info(PRTSP_MESSAGE msg, std::string_view transport) { + auto standalone = rtsp_option_value(msg, "X-GS-ClientPort"sv); + auto transport_param = rtsp_transport_param_value(transport, "X-GS-ClientPort"sv); + + client_port_info_t info; + if (!standalone.empty()) { + info.raw = std::move(standalone); + info.source = "standalone-header"; + } else if (!transport_param.empty()) { + info.raw = std::move(transport_param); + info.source = "transport-param"; + } else { + info.source = "missing"; + return info; + } + + auto split = std::string_view {info.raw}.find('-'); + if (split == std::string_view::npos) { + info.rtp = rtsp_parse_u16(info.raw); + } else { + std::string_view raw {info.raw}; + info.rtp = rtsp_parse_u16(raw.substr(0, split)); + info.rtcp = rtsp_parse_u16(raw.substr(split + 1)); + } + + return info; + } + + std::string rtsp_optional_port_to_string(const std::optional &port) { + return port ? std::to_string(*port) : ""s; + } + std::string rtsp_message_to_string(PRTSP_MESSAGE msg) { std::ostringstream ss; @@ -896,15 +1002,18 @@ namespace rtsp_stream { auto end = std::find(begin, std::end(target), '/'); std::string_view type {begin, (size_t) std::distance(begin, end)}; std::string_view stream_id {begin, static_cast(std::distance(begin, std::end(target)))}; - const auto client_port = rtsp_option_value(req.get(), "X-GS-ClientPort"sv); const auto transport = rtsp_option_value(req.get(), "Transport"sv); + auto client_port = rtsp_client_port_info(req.get(), transport); BOOST_LOG(info) << "STREAM_DIAG RTSP SETUP request" << " session_id="sv << session.id << " channel="sv << type << " stream_id="sv << stream_id << " target="sv << target - << " x_gs_client_port="sv << (client_port.empty() ? ""s : client_port) + << " x_gs_client_port="sv << (client_port.raw.empty() ? ""s : client_port.raw) + << " x_gs_client_port_source="sv << client_port.source + << " client_rtp_port="sv << rtsp_optional_port_to_string(client_port.rtp) + << " client_rtcp_port="sv << rtsp_optional_port_to_string(client_port.rtcp) << " transport="sv << (transport.empty() ? ""s : transport) << std::endl << "---BEGIN STREAM_DIAG RTSP SETUP REQUEST---"sv << std::endl @@ -914,10 +1023,13 @@ namespace rtsp_stream { std::uint16_t port; if (type == "audio"sv) { port = net::map_port(stream::AUDIO_STREAM_PORT); + session.audio_client_port = client_port.rtp; } else if (type == "video"sv) { port = net::map_port(stream::VIDEO_STREAM_PORT); + session.video_client_port = client_port.rtp; } else if (type == "control"sv) { port = net::map_port(stream::CONTROL_PORT); + session.control_client_port = client_port.rtp; } else { cmd_not_found(sock, session, std::move(req)); @@ -954,7 +1066,10 @@ namespace rtsp_stream { << " channel="sv << type << " stream_id="sv << stream_id << " server_udp_port="sv << port - << " x_gs_client_port="sv << (client_port.empty() ? ""s : client_port) + << " x_gs_client_port="sv << (client_port.raw.empty() ? ""s : client_port.raw) + << " x_gs_client_port_source="sv << client_port.source + << " client_rtp_port="sv << rtsp_optional_port_to_string(client_port.rtp) + << " client_rtcp_port="sv << rtsp_optional_port_to_string(client_port.rtcp) << " payload_option="sv << payload_option.option << " payload_value="sv << payload_option.content; @@ -963,7 +1078,10 @@ namespace rtsp_stream { << " channel="sv << type << " stream_id="sv << stream_id << " server_udp_port="sv << port - << " x_gs_client_port="sv << (client_port.empty() ? ""s : client_port) + << " x_gs_client_port="sv << (client_port.raw.empty() ? ""s : client_port.raw) + << " x_gs_client_port_source="sv << client_port.source + << " client_rtp_port="sv << rtsp_optional_port_to_string(client_port.rtp) + << " client_rtcp_port="sv << rtsp_optional_port_to_string(client_port.rtcp) << std::endl << "---BEGIN STREAM_DIAG RTSP SETUP RESPONSE---"sv << std::endl << rtsp_response_to_string(200, "OK", &seqn, {}) diff --git a/src/rtsp.h b/src/rtsp.h index 6dfa16e12e8..98650619da5 100644 --- a/src/rtsp.h +++ b/src/rtsp.h @@ -4,8 +4,10 @@ */ #pragma once -// standard includes #include +#include +#include +#include // local includes #include "crypto.h" @@ -22,6 +24,9 @@ namespace rtsp_stream { std::string av_ping_payload; uint32_t control_connect_data; + std::optional audio_client_port; + std::optional video_client_port; + std::optional control_client_port; bool host_audio; std::string unique_id; diff --git a/src/stream.cpp b/src/stream.cpp index 33abca509f1..4babdaa6f2f 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -5,8 +5,12 @@ // standard includes #include +#include +#include +#include #include #include +#include #include #include @@ -107,6 +111,34 @@ namespace stream { return endpoint.port(); } + std::string stream_diag_endpoint_to_string(const udp::endpoint &peer) { + boost::system::error_code ec; + auto address = peer.address().to_string(ec); + if (ec) { + address = ""; + } + + return std::format("{}:{}", address, peer.port()); + } + + std::string stream_diag_optional_port_to_string(const std::optional &port) { + return port ? std::to_string(*port) : ""s; + } + + bool stream_diag_reuse_audio_peer_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_REUSE_AUDIO_PEER"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + #pragma pack(push, 1) struct video_short_frame_header_t { @@ -443,6 +475,14 @@ namespace stream { std::atomic_uint64_t video_udp_sent {0}; std::atomic_uint64_t audio_udp_sent {0}; std::atomic_uint64_t control_udp_sent {0}; + + std::optional video_rtsp_client_port; + std::optional audio_rtsp_client_port; + std::optional control_rtsp_client_port; + + std::atomic_bool audio_only_video_probe_logged {false}; + std::atomic_bool audio_only_control_probe_logged {false}; + std::atomic_bool audio_peer_video_promoted {false}; } stream_diag; safe::mail_raw_t::event_t shutdown_event; @@ -464,6 +504,9 @@ namespace stream { << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() << " audio_udp_sent="sv << session->stream_diag.audio_udp_sent.load() << " control_udp_sent="sv << session->stream_diag.control_udp_sent.load() + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) << " audio_raised_alone_blocks_video_or_control=0"; } @@ -1218,6 +1261,29 @@ namespace stream { session::stop(*session); } + auto session_start_time = session->pingTimeout - config::stream.ping_timeout; + if (now - session_start_time >= 1s && + session->stream_diag.audio_ping_ready.load() && + !session->stream_diag.video_ping_ready.load() && + !session->stream_diag.control_peer_ready.load() && + session->stream_diag.video_udp_received.load() == 0 && + session->stream_diag.control_udp_received.load() == 0) { + bool already_logged = session->stream_diag.audio_only_control_probe_logged.exchange(true); + if (!already_logged) { + BOOST_LOG(warning) << "STREAM_DIAG audio-only peer probe" + << " channel=CONTROL" + << " launch_session_id="sv << session->launch_session_id + << " audio_peer="sv << stream_diag_endpoint_to_string(session->audio.peer) + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " reuse_audio_peer_enabled="sv << stream_diag_reuse_audio_peer_enabled() + << " control_peer_promotion=not_attempted" + << " reason=audio ping accepted but no control ENet activity after diagnostic delay; CONTROL uses ENet peer state, not a raw UDP endpoint"; + stream_diag_log_ready_state("ready state during audio-only control probe", session, "CONTROL"sv); + } + } + if (session->state.load(std::memory_order_acquire) == session::state_e::STOPPING) { pos = server->_sessions->erase(pos); @@ -2062,10 +2128,52 @@ namespace stream { while (current_time - start_time < config::stream.ping_timeout) { auto delta_time = current_time - start_time; + auto remaining_time = std::chrono::duration_cast(config::stream.ping_timeout - delta_time); + auto wait_time = std::min(remaining_time, 250ms); - auto msg_opt = messages->pop(config::stream.ping_timeout - delta_time); + auto msg_opt = messages->pop(wait_time); if (!msg_opt) { - break; + current_time = std::chrono::steady_clock::now(); + + if (type == socket_e::video && + current_time - start_time >= 1s && + session->stream_diag.audio_ping_ready.load() && + !session->stream_diag.video_ping_ready.load() && + !session->stream_diag.control_peer_ready.load() && + session->stream_diag.video_udp_received.load() == 0 && + session->stream_diag.control_udp_received.load() == 0) { + bool already_logged = session->stream_diag.audio_only_video_probe_logged.exchange(true); + if (!already_logged) { + BOOST_LOG(warning) << "STREAM_DIAG audio-only peer probe" + << " channel=VIDEO" + << " launch_session_id="sv << session->launch_session_id + << " elapsed_ms="sv << std::chrono::duration_cast(current_time - start_time).count() + << " audio_peer="sv << stream_diag_endpoint_to_string(session->audio.peer) + << " video_peer_before="sv << stream_diag_endpoint_to_string(peer) + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " reuse_audio_peer_enabled="sv << stream_diag_reuse_audio_peer_enabled() + << " reason=audio ping accepted but no video UDP or control ENet activity after diagnostic delay"; + } + + if (stream_diag_reuse_audio_peer_enabled() && session->audio.peer.port() != 0) { + peer = session->audio.peer; + session->stream_diag.video_ping_ready.store(true); + session->stream_diag.audio_peer_video_promoted.store(true); + BOOST_LOG(warning) << "STREAM_DIAG experimental audio peer promotion" + << " channel=VIDEO" + << " launch_session_id="sv << session->launch_session_id + << " promoted_video_peer="sv << stream_diag_endpoint_to_string(peer) + << " source=AUDIO" + << " control_peer_promotion=not_attempted" + << " control_reason=CONTROL uses ENet and no control peer exists to reuse audio UDP endpoint"; + stream_diag_log_ready_state("ready state after experimental audio peer promotion", session, channel); + return 0; + } + } + + continue; } TUPLE_2D_REF(recv_peer, msg, *msg_opt); @@ -2268,7 +2376,11 @@ namespace stream { << " video_udp_port="sv << net::map_port(VIDEO_STREAM_PORT) << " control_udp_port="sv << net::map_port(CONTROL_PORT) << " audio_udp_port="sv << net::map_port(AUDIO_STREAM_PORT) + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session.stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session.stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session.stream_diag.control_rtsp_client_port) << " ping_timeout_ms="sv << config::stream.ping_timeout.count() + << " experimental_reuse_audio_peer="sv << stream_diag_reuse_audio_peer_enabled() << " audio_and_video_waiters_independent=1" << " audio_raised_alone_blocks_video_or_control=0"; @@ -2316,6 +2428,9 @@ namespace stream { session->launch_session_id = launch_session.id; session->config = config; + session->stream_diag.audio_rtsp_client_port = launch_session.audio_client_port; + session->stream_diag.video_rtsp_client_port = launch_session.video_client_port; + session->stream_diag.control_rtsp_client_port = launch_session.control_client_port; session->control.connect_data = launch_session.control_connect_data; session->control.feedback_queue = mail->queue(mail::gamepad_feedback); From 5241cfd75231fe0873cce7616e71bea3c5ef851a Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 19:00:56 -0400 Subject: [PATCH 07/21] Fix stream endpoint diagnostic build --- src/stream.cpp | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/stream.cpp b/src/stream.cpp index 4babdaa6f2f..d53a0060bee 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -112,10 +112,11 @@ namespace stream { } std::string stream_diag_endpoint_to_string(const udp::endpoint &peer) { - boost::system::error_code ec; - auto address = peer.address().to_string(ec); - if (ec) { - address = ""; + std::string address; + try { + address = peer.address().to_string(); + } catch (const std::exception &e) { + address = std::string {"'; } return std::format("{}:{}", address, peer.port()); From 0f496827e7ce265c632170734bab34ec62097e6d Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 19:17:05 -0400 Subject: [PATCH 08/21] Add control ENet and video peer diagnostics --- src/stream.cpp | 326 +++++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 305 insertions(+), 21 deletions(-) diff --git a/src/stream.cpp b/src/stream.cpp index d53a0060bee..dbaad6b5de3 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -140,6 +140,29 @@ namespace stream { return enabled; } + bool stream_diag_control_connect_client_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_CONTROL_CONNECT_CLIENT"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + + std::string_view stream_diag_video_peer_mode() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_VIDEO_PEER_MODE"); + if (value && *value) { + return value; + } + + return stream_diag_reuse_audio_peer_enabled() ? "audio-peer"sv : "off"sv; + } + #pragma pack(push, 1) struct video_short_frame_header_t { @@ -330,10 +353,17 @@ namespace stream { class control_server_t { public: int bind(net::af_e address_family, std::uint16_t port) { - BOOST_LOG(info) << "STREAM_DIAG udp bind begin channel=CONTROL local_port="sv << port; + const auto bind_address = net::get_bind_address(address_family); + BOOST_LOG(info) << "STREAM_DIAG udp bind begin channel=CONTROL" + << " bind_addr="sv << bind_address + << " local_port="sv << port + << " raw_udp_visibility=unavailable_enet_owns_socket"; _host = net::host_create(address_family, _addr, port); BOOST_LOG(info) << "STREAM_DIAG udp bind "sv << (_host ? "success"sv : "failed"sv) - << " channel=CONTROL local_port="sv << port; + << " channel=CONTROL" + << " bind_addr="sv << bind_address + << " local_port="sv << port + << " raw_udp_visibility=unavailable_enet_owns_socket"; return !(bool) _host; } @@ -349,6 +379,7 @@ namespace stream { // broadcast_ctx_t refers to control_server_t // Therefore, iterate is implemented further down the source file void iterate(std::chrono::milliseconds timeout); + net::peer_t connect_to_client(session_t *session); /** * @brief Call the handler for a given control stream message. @@ -378,6 +409,7 @@ namespace stream { // ENet peer to session mapping for sessions with a peer connected sync_util::sync_t> _peer_to_session; + std::uint64_t _service_poll_count = 0; ENetAddress _addr; net::host_t _host; }; @@ -484,6 +516,9 @@ namespace stream { std::atomic_bool audio_only_video_probe_logged {false}; std::atomic_bool audio_only_control_probe_logged {false}; std::atomic_bool audio_peer_video_promoted {false}; + std::atomic_bool rtsp_client_port_video_promoted {false}; + std::atomic_bool control_connect_probe_attempted {false}; + std::atomic_bool control_connect_probe_peer_created {false}; } stream_diag; safe::mail_raw_t::event_t shutdown_event; @@ -508,6 +543,13 @@ namespace stream { << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " expected_connect_data="sv << session->control.connect_data + << " controlProtocolType="sv << session->config.controlProtocolType + << " mlFeatureFlags="sv << session->config.mlFeatureFlags + << " experimental_video_peer_mode="sv << stream_diag_video_peer_mode() + << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() + << " control_connect_probe_attempted="sv << session->stream_diag.control_connect_probe_attempted.load() + << " control_connect_probe_peer_created="sv << session->stream_diag.control_connect_probe_peer_created.load() << " audio_raised_alone_blocks_video_or_control=0"; } @@ -603,6 +645,55 @@ namespace stream { return 0; } + net::peer_t control_server_t::connect_to_client(session_t *session) { + if (!_host) { + BOOST_LOG(warning) << "STREAM_DIAG control connect probe skipped" + << " reason=no_enet_host" + << " launch_session_id="sv << session->launch_session_id; + return nullptr; + } + + if (!session->stream_diag.control_rtsp_client_port) { + BOOST_LOG(warning) << "STREAM_DIAG control connect probe skipped" + << " reason=missing_rtsp_control_client_port" + << " launch_session_id="sv << session->launch_session_id + << " expected_client_address="sv << session->control.expected_peer_address + << " expected_connect_data="sv << session->control.connect_data; + return nullptr; + } + + ENetAddress address {}; + const auto port = *session->stream_diag.control_rtsp_client_port; + if (enet_address_set_host(&address, session->control.expected_peer_address.c_str()) != 0) { + BOOST_LOG(warning) << "STREAM_DIAG control connect probe skipped" + << " reason=bad_expected_client_address" + << " launch_session_id="sv << session->launch_session_id + << " expected_client_address="sv << session->control.expected_peer_address + << " rtsp_control_client_port="sv << port + << " expected_connect_data="sv << session->control.connect_data; + return nullptr; + } + enet_address_set_port(&address, port); + + BOOST_LOG(warning) << "STREAM_DIAG control connect probe begin" + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << session->control.expected_peer_address << ':' << port + << " local_port="sv << net::map_port(CONTROL_PORT) + << " expected_connect_data="sv << session->control.connect_data + << " controlProtocolType="sv << session->config.controlProtocolType + << " mlFeatureFlags="sv << session->config.mlFeatureFlags; + + auto peer = enet_host_connect(_host.get(), &address, 1, session->control.connect_data); + session->stream_diag.control_connect_probe_peer_created.store(peer != nullptr); + BOOST_LOG(warning) << "STREAM_DIAG control connect probe result" + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << session->control.expected_peer_address << ':' << port + << " enet_host_connect_peer_created="sv << (peer != nullptr) + << " expected_connect_data="sv << session->control.connect_data; + + return peer; + } + session_t *control_server_t::get_session(const net::peer_t peer, uint32_t connect_data) { { // Fast path - look up existing session by peer @@ -616,6 +707,10 @@ namespace stream { // Slow path - process new session TUPLE_2D(peer_port, peer_addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); auto lg = _sessions.lock(); + BOOST_LOG(info) << "STREAM_DIAG control session lookup" + << " remote="sv << peer_addr << ':' << peer_port + << " connect_data="sv << connect_data + << " active_sessions="sv << _sessions->size(); for (auto pos = std::begin(*_sessions); pos != std::end(*_sessions); ++pos) { auto session_p = *pos; @@ -628,15 +723,52 @@ namespace stream { // Only fall back to IP address matching for clients without session ID support. if (session_p->config.mlFeatureFlags & ML_FF_SESSION_ID_V1) { if (session_p->control.connect_data != connect_data) { + BOOST_LOG(info) << "STREAM_DIAG control session candidate mismatch" + << " reason=connect_data" + << " launch_session_id="sv << session_p->launch_session_id + << " remote="sv << peer_addr << ':' << peer_port + << " got_connect_data="sv << connect_data + << " expected_connect_data="sv << session_p->control.connect_data + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) + << " controlProtocolType="sv << session_p->config.controlProtocolType + << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; continue; } else { BOOST_LOG(debug) << "Initialized new control stream session by connect data match [v2]"sv; + BOOST_LOG(info) << "STREAM_DIAG control session candidate matched" + << " match=connect_data" + << " launch_session_id="sv << session_p->launch_session_id + << " remote="sv << peer_addr << ':' << peer_port + << " connect_data="sv << connect_data + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) + << " controlProtocolType="sv << session_p->config.controlProtocolType + << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; } } else { if (session_p->control.expected_peer_address != peer_addr) { + BOOST_LOG(info) << "STREAM_DIAG control session candidate mismatch" + << " reason=peer_address" + << " launch_session_id="sv << session_p->launch_session_id + << " remote="sv << peer_addr << ':' << peer_port + << " expected_peer_address="sv << session_p->control.expected_peer_address + << " got_connect_data="sv << connect_data + << " expected_connect_data="sv << session_p->control.connect_data + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) + << " controlProtocolType="sv << session_p->config.controlProtocolType + << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; continue; } else { BOOST_LOG(debug) << "Initialized new control stream session by IP address match [v1]"sv; + BOOST_LOG(info) << "STREAM_DIAG control session candidate matched" + << " match=peer_address" + << " launch_session_id="sv << session_p->launch_session_id + << " remote="sv << peer_addr << ':' << peer_port + << " expected_peer_address="sv << session_p->control.expected_peer_address + << " got_connect_data="sv << connect_data + << " expected_connect_data="sv << session_p->control.connect_data + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) + << " controlProtocolType="sv << session_p->config.controlProtocolType + << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; } } @@ -673,6 +805,10 @@ namespace stream { return session_p; } + BOOST_LOG(warning) << "STREAM_DIAG control session lookup failed" + << " remote="sv << peer_addr << ':' << peer_port + << " connect_data="sv << connect_data + << " active_sessions="sv << _sessions->size(); return nullptr; } @@ -705,6 +841,70 @@ namespace stream { void control_server_t::iterate(std::chrono::milliseconds timeout) { ENetEvent event; auto res = enet_host_service(_host.get(), &event, (enet_uint32) timeout.count()); + ++_service_poll_count; + + if (res <= 0) { + std::size_t active_sessions = 0; + std::size_t awaiting_control_sessions = 0; + std::string expected_client_address = ""; + std::string rtsp_control_client_port = ""; + std::uint32_t expected_connect_data = 0; + int control_protocol_type = 0; + std::uint32_t ml_feature_flags = 0; + + { + auto lg = _sessions.lock(); + active_sessions = _sessions->size(); + for (auto session_p : *_sessions) { + if (!session_p->control.peer) { + ++awaiting_control_sessions; + if (expected_client_address == "") { + expected_client_address = session_p->control.expected_peer_address; + rtsp_control_client_port = stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port); + expected_connect_data = session_p->control.connect_data; + control_protocol_type = session_p->config.controlProtocolType; + ml_feature_flags = session_p->config.mlFeatureFlags; + } + } + } + } + + if (res < 0) { + BOOST_LOG(error) << "STREAM_DIAG enet_host_service result" + << " channel=CONTROL" + << " res="sv << res + << " event=NONE" + << " poll_count="sv << _service_poll_count + << " timeout_ms="sv << timeout.count() + << " local_port="sv << net::map_port(CONTROL_PORT) + << " active_sessions="sv << active_sessions + << " awaiting_control_sessions="sv << awaiting_control_sessions + << " expected_client_address="sv << expected_client_address + << " rtsp_control_client_port="sv << rtsp_control_client_port + << " expected_connect_data="sv << expected_connect_data + << " controlProtocolType="sv << control_protocol_type + << " mlFeatureFlags="sv << ml_feature_flags + << " raw_udp_visibility=unavailable_enet_owns_socket"; + } else if (_service_poll_count <= 3 || (_service_poll_count % 20 == 0 && awaiting_control_sessions > 0)) { + BOOST_LOG(info) << "STREAM_DIAG enet_host_service result" + << " channel=CONTROL" + << " res="sv << res + << " event=NONE" + << " poll_count="sv << _service_poll_count + << " timeout_ms="sv << timeout.count() + << " local_port="sv << net::map_port(CONTROL_PORT) + << " active_sessions="sv << active_sessions + << " awaiting_control_sessions="sv << awaiting_control_sessions + << " expected_client_address="sv << expected_client_address + << " rtsp_control_client_port="sv << rtsp_control_client_port + << " expected_connect_data="sv << expected_connect_data + << " controlProtocolType="sv << control_protocol_type + << " mlFeatureFlags="sv << ml_feature_flags + << " raw_udp_visibility=unavailable_enet_owns_socket"; + } + + return; + } if (res > 0) { TUPLE_2D(event_port, event_addr, platf::from_sockaddr_ex((sockaddr *) &event.peer->address.address)); @@ -723,6 +923,15 @@ namespace stream { event_type = "NONE"; break; } + BOOST_LOG(info) << "STREAM_DIAG enet_host_service result" + << " channel=CONTROL" + << " res="sv << res + << " event="sv << event_type + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << event_addr << ':' << event_port + << " bytes="sv << (event.packet ? event.packet->dataLength : 0) + << " connect_data="sv << event.data + << " raw_udp_visibility=enet_event_only"; BOOST_LOG(info) << "STREAM_DIAG udp receive" << " channel=CONTROL" << " event="sv << event_type @@ -1255,6 +1464,14 @@ namespace stream { << " launch_session_id="sv << session->launch_session_id << " wait_condition=no control ENet activity before session pingTimeout" << " remote="sv << address + << " expected_client_address="sv << session->control.expected_peer_address + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " expected_connect_data="sv << session->control.connect_data + << " controlProtocolType="sv << session->config.controlProtocolType + << " mlFeatureFlags="sv << session->config.mlFeatureFlags + << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() + << " control_connect_probe_attempted="sv << session->stream_diag.control_connect_probe_attempted.load() + << " control_connect_probe_peer_created="sv << session->stream_diag.control_connect_probe_peer_created.load() << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() << " audio_raised_alone_blocks_video_or_control=0"; stream_diag_log_ready_state("ready state at control ping timeout", session, "CONTROL"sv); @@ -1263,6 +1480,21 @@ namespace stream { } auto session_start_time = session->pingTimeout - config::stream.ping_timeout; + if (now - session_start_time >= 1s && + !session->control.peer && + stream_diag_control_connect_client_enabled() && + !session->stream_diag.control_connect_probe_attempted.exchange(true)) { + BOOST_LOG(warning) << "STREAM_DIAG control connect probe scheduling" + << " launch_session_id="sv << session->launch_session_id + << " reason=no_control_enet_after_diagnostic_delay" + << " expected_client_address="sv << session->control.expected_peer_address + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " expected_connect_data="sv << session->control.connect_data + << " controlProtocolType="sv << session->config.controlProtocolType + << " mlFeatureFlags="sv << session->config.mlFeatureFlags; + server->connect_to_client(session); + } + if (now - session_start_time >= 1s && session->stream_diag.audio_ping_ready.load() && !session->stream_diag.video_ping_ready.load() && @@ -2111,7 +2343,11 @@ namespace stream { << " initial_peer="sv << peer.address().to_string() << ':' << peer.port() << " timeout_ms="sv << timeout.count() << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() - << " ml_session_id_v1="sv << static_cast(session->config.mlFeatureFlags & ML_FF_SESSION_ID_V1); + << " ml_session_id_v1="sv << static_cast(session->config.mlFeatureFlags & ML_FF_SESSION_ID_V1) + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " experimental_video_peer_mode="sv << stream_diag_video_peer_mode(); stream_diag_log_ready_state("ready state before initial ping wait", session, channel); auto fg = util::fail_guard([&]() { @@ -2138,27 +2374,66 @@ namespace stream { if (type == socket_e::video && current_time - start_time >= 1s && - session->stream_diag.audio_ping_ready.load() && !session->stream_diag.video_ping_ready.load() && - !session->stream_diag.control_peer_ready.load() && - session->stream_diag.video_udp_received.load() == 0 && - session->stream_diag.control_udp_received.load() == 0) { - bool already_logged = session->stream_diag.audio_only_video_probe_logged.exchange(true); - if (!already_logged) { - BOOST_LOG(warning) << "STREAM_DIAG audio-only peer probe" - << " channel=VIDEO" - << " launch_session_id="sv << session->launch_session_id - << " elapsed_ms="sv << std::chrono::duration_cast(current_time - start_time).count() - << " audio_peer="sv << stream_diag_endpoint_to_string(session->audio.peer) - << " video_peer_before="sv << stream_diag_endpoint_to_string(peer) - << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) - << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) - << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) - << " reuse_audio_peer_enabled="sv << stream_diag_reuse_audio_peer_enabled() - << " reason=audio ping accepted but no video UDP or control ENet activity after diagnostic delay"; + session->stream_diag.video_udp_received.load() == 0) { + auto video_peer_mode = stream_diag_video_peer_mode(); + if (session->stream_diag.audio_ping_ready.load() && + !session->stream_diag.control_peer_ready.load() && + session->stream_diag.control_udp_received.load() == 0) { + bool already_logged = session->stream_diag.audio_only_video_probe_logged.exchange(true); + if (!already_logged) { + BOOST_LOG(warning) << "STREAM_DIAG audio-only peer probe" + << " channel=VIDEO" + << " launch_session_id="sv << session->launch_session_id + << " elapsed_ms="sv << std::chrono::duration_cast(current_time - start_time).count() + << " audio_peer="sv << stream_diag_endpoint_to_string(session->audio.peer) + << " video_peer_before="sv << stream_diag_endpoint_to_string(peer) + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " experimental_video_peer_mode="sv << video_peer_mode + << " reuse_audio_peer_enabled="sv << stream_diag_reuse_audio_peer_enabled() + << " reason=audio ping accepted but no video UDP or control ENet activity after diagnostic delay"; + } + } + + if (video_peer_mode == "rtsp-client-port"sv && + !session->stream_diag.rtsp_client_port_video_promoted.exchange(true)) { + if (!session->stream_diag.video_rtsp_client_port) { + BOOST_LOG(warning) << "STREAM_DIAG experimental rtsp client port video promotion skipped" + << " channel=VIDEO" + << " launch_session_id="sv << session->launch_session_id + << " reason=missing_rtsp_video_client_port" + << " expected_client_address="sv << session->control.expected_peer_address; + } else { + boost::system::error_code ec; + auto address = boost::asio::ip::make_address(session->control.expected_peer_address, ec); + if (ec) { + BOOST_LOG(warning) << "STREAM_DIAG experimental rtsp client port video promotion skipped" + << " channel=VIDEO" + << " launch_session_id="sv << session->launch_session_id + << " reason=bad_expected_client_address" + << " expected_client_address="sv << session->control.expected_peer_address + << " error="sv << ec.message(); + } else { + peer.address(address); + peer.port(*session->stream_diag.video_rtsp_client_port); + session->stream_diag.video_ping_ready.store(true); + BOOST_LOG(warning) << "STREAM_DIAG experimental rtsp client port video promotion" + << " channel=VIDEO" + << " launch_session_id="sv << session->launch_session_id + << " promoted_video_peer="sv << stream_diag_endpoint_to_string(peer) + << " expected_client_address="sv << session->control.expected_peer_address + << " rtsp_video_client_port="sv << *session->stream_diag.video_rtsp_client_port + << " source=RTSP_X_GS_ClientPort" + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load(); + stream_diag_log_ready_state("ready state after experimental rtsp client port video promotion", session, channel); + return 0; + } + } } - if (stream_diag_reuse_audio_peer_enabled() && session->audio.peer.port() != 0) { + if (video_peer_mode == "audio-peer"sv && session->audio.peer.port() != 0) { peer = session->audio.peer; session->stream_diag.video_ping_ready.store(true); session->stream_diag.audio_peer_video_promoted.store(true); @@ -2230,6 +2505,10 @@ namespace stream { << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() << " expected_payload="sv << util::hex_vec(expected_payload) << " last_peer="sv << peer.address().to_string() << ':' << peer.port() + << " rtsp_video_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.video_rtsp_client_port) + << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.audio_rtsp_client_port) + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session->stream_diag.control_rtsp_client_port) + << " experimental_video_peer_mode="sv << stream_diag_video_peer_mode() << " audio_raised_alone_blocks_video_or_control=0"; stream_diag_log_ready_state("ready state at initial ping timeout", session, channel); BOOST_LOG(error) << "Initial Ping Timeout"sv; @@ -2381,7 +2660,12 @@ namespace stream { << " rtsp_audio_client_port="sv << stream_diag_optional_port_to_string(session.stream_diag.audio_rtsp_client_port) << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session.stream_diag.control_rtsp_client_port) << " ping_timeout_ms="sv << config::stream.ping_timeout.count() + << " expected_connect_data="sv << session.control.connect_data + << " controlProtocolType="sv << session.config.controlProtocolType + << " mlFeatureFlags="sv << session.config.mlFeatureFlags + << " experimental_video_peer_mode="sv << stream_diag_video_peer_mode() << " experimental_reuse_audio_peer="sv << stream_diag_reuse_audio_peer_enabled() + << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() << " audio_and_video_waiters_independent=1" << " audio_raised_alone_blocks_video_or_control=0"; From d4beb3c38c6e8aebe301884eb7614b664d7ee180 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 19:43:34 -0400 Subject: [PATCH 09/21] Add zero connect-data control diagnostic fallback --- src/stream.cpp | 117 ++++++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 105 insertions(+), 12 deletions(-) diff --git a/src/stream.cpp b/src/stream.cpp index dbaad6b5de3..5c7f3f6efca 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -154,6 +154,20 @@ namespace stream { return enabled; } + bool stream_diag_accept_control_connect_data_zero_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_ACCEPT_CONTROL_CONNECT_DATA_ZERO"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + std::string_view stream_diag_video_peer_mode() { auto value = std::getenv("SUNSHINE_STREAM_DIAG_VIDEO_PEER_MODE"); if (value && *value) { @@ -519,6 +533,8 @@ namespace stream { std::atomic_bool rtsp_client_port_video_promoted {false}; std::atomic_bool control_connect_probe_attempted {false}; std::atomic_bool control_connect_probe_peer_created {false}; + std::atomic_bool control_connect_data_zero_fallback_used {false}; + std::atomic_uint64_t control_encrypted_packets_received {0}; } stream_diag; safe::mail_raw_t::event_t shutdown_event; @@ -550,6 +566,9 @@ namespace stream { << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() << " control_connect_probe_attempted="sv << session->stream_diag.control_connect_probe_attempted.load() << " control_connect_probe_peer_created="sv << session->stream_diag.control_connect_probe_peer_created.load() + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " control_connect_data_zero_fallback_used="sv << session->stream_diag.control_connect_data_zero_fallback_used.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() << " audio_raised_alone_blocks_video_or_control=0"; } @@ -707,10 +726,18 @@ namespace stream { // Slow path - process new session TUPLE_2D(peer_port, peer_addr, platf::from_sockaddr_ex((sockaddr *) &peer->address.address)); auto lg = _sessions.lock(); + auto awaiting_control_sessions = static_cast(0); + for (auto session_p : *_sessions) { + if (!session_p->control.peer) { + ++awaiting_control_sessions; + } + } BOOST_LOG(info) << "STREAM_DIAG control session lookup" << " remote="sv << peer_addr << ':' << peer_port << " connect_data="sv << connect_data - << " active_sessions="sv << _sessions->size(); + << " active_sessions="sv << _sessions->size() + << " awaiting_control_sessions="sv << awaiting_control_sessions + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled(); for (auto pos = std::begin(*_sessions); pos != std::end(*_sessions); ++pos) { auto session_p = *pos; @@ -723,16 +750,39 @@ namespace stream { // Only fall back to IP address matching for clients without session ID support. if (session_p->config.mlFeatureFlags & ML_FF_SESSION_ID_V1) { if (session_p->control.connect_data != connect_data) { - BOOST_LOG(info) << "STREAM_DIAG control session candidate mismatch" - << " reason=connect_data" - << " launch_session_id="sv << session_p->launch_session_id - << " remote="sv << peer_addr << ':' << peer_port - << " got_connect_data="sv << connect_data - << " expected_connect_data="sv << session_p->control.connect_data - << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) - << " controlProtocolType="sv << session_p->config.controlProtocolType - << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; - continue; + const auto can_accept_zero_connect_data = + stream_diag_accept_control_connect_data_zero_enabled() && + connect_data == 0 && + awaiting_control_sessions == 1 && + session_p->control.expected_peer_address == peer_addr; + if (can_accept_zero_connect_data) { + session_p->stream_diag.control_connect_data_zero_fallback_used.store(true); + BOOST_LOG(warning) << "STREAM_DIAG control connect_data zero fallback used" + << " launch_session_id="sv << session_p->launch_session_id + << " remote="sv << peer_addr << ':' << peer_port + << " got_connect_data=0" + << " expected_connect_data="sv << session_p->control.connect_data + << " expected_peer_address="sv << session_p->control.expected_peer_address + << " awaiting_control_sessions="sv << awaiting_control_sessions + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) + << " controlProtocolType="sv << session_p->config.controlProtocolType + << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; + } else { + BOOST_LOG(info) << "STREAM_DIAG control session candidate mismatch" + << " reason=connect_data" + << " launch_session_id="sv << session_p->launch_session_id + << " remote="sv << peer_addr << ':' << peer_port + << " got_connect_data="sv << connect_data + << " expected_connect_data="sv << session_p->control.connect_data + << " expected_peer_address="sv << session_p->control.expected_peer_address + << " awaiting_control_sessions="sv << awaiting_control_sessions + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " zero_fallback_conditions_met="sv << can_accept_zero_connect_data + << " rtsp_control_client_port="sv << stream_diag_optional_port_to_string(session_p->stream_diag.control_rtsp_client_port) + << " controlProtocolType="sv << session_p->config.controlProtocolType + << " mlFeatureFlags="sv << session_p->config.mlFeatureFlags; + continue; + } } else { BOOST_LOG(debug) << "Initialized new control stream session by connect data match [v2]"sv; BOOST_LOG(info) << "STREAM_DIAG control session candidate matched" @@ -796,7 +846,11 @@ namespace stream { << " local_port="sv << net::map_port(CONTROL_PORT) << " remote="sv << peer_addr << ':' << peer_port << " connect_data="sv << connect_data - << " expected_peer_address="sv << session_p->control.expected_peer_address; + << " expected_peer_address="sv << session_p->control.expected_peer_address + << " expected_connect_data="sv << session_p->control.connect_data + << " connect_data_zero_fallback_used="sv << session_p->stream_diag.control_connect_data_zero_fallback_used.load() + << " control_peer_ready="sv << session_p->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session_p->stream_diag.control_encrypted_packets_received.load(); stream_diag_log_ready_state("ready state after control peer", session_p, "CONTROL"sv); // Insert this into the map for O(1) lookups in the future @@ -851,6 +905,8 @@ namespace stream { std::uint32_t expected_connect_data = 0; int control_protocol_type = 0; std::uint32_t ml_feature_flags = 0; + bool zero_fallback_used = false; + std::uint64_t encrypted_packets_received = 0; { auto lg = _sessions.lock(); @@ -864,6 +920,8 @@ namespace stream { expected_connect_data = session_p->control.connect_data; control_protocol_type = session_p->config.controlProtocolType; ml_feature_flags = session_p->config.mlFeatureFlags; + zero_fallback_used = session_p->stream_diag.control_connect_data_zero_fallback_used.load(); + encrypted_packets_received = session_p->stream_diag.control_encrypted_packets_received.load(); } } } @@ -884,6 +942,9 @@ namespace stream { << " expected_connect_data="sv << expected_connect_data << " controlProtocolType="sv << control_protocol_type << " mlFeatureFlags="sv << ml_feature_flags + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " control_connect_data_zero_fallback_used="sv << zero_fallback_used + << " control_encrypted_packets_received="sv << encrypted_packets_received << " raw_udp_visibility=unavailable_enet_owns_socket"; } else if (_service_poll_count <= 3 || (_service_poll_count % 20 == 0 && awaiting_control_sessions > 0)) { BOOST_LOG(info) << "STREAM_DIAG enet_host_service result" @@ -900,6 +961,9 @@ namespace stream { << " expected_connect_data="sv << expected_connect_data << " controlProtocolType="sv << control_protocol_type << " mlFeatureFlags="sv << ml_feature_flags + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " control_connect_data_zero_fallback_used="sv << zero_fallback_used + << " control_encrypted_packets_received="sv << encrypted_packets_received << " raw_udp_visibility=unavailable_enet_owns_socket"; } @@ -952,6 +1016,18 @@ namespace stream { } session->pingTimeout = std::chrono::steady_clock::now() + config::stream.ping_timeout; + if (session->stream_diag.control_connect_data_zero_fallback_used.load()) { + BOOST_LOG(warning) << "STREAM_DIAG control connect_data zero fallback event" + << " launch_session_id="sv << session->launch_session_id + << " event="sv << event_type + << " remote="sv << event_addr << ':' << event_port + << " got_connect_data="sv << event.data + << " expected_connect_data="sv << session->control.connect_data + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_udp_received="sv << session->stream_diag.control_udp_received.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " ping_timeout_extended=1"; + } switch (event.type) { case ENET_EVENT_TYPE_RECEIVE: @@ -960,6 +1036,18 @@ namespace stream { auto type = *(std::uint16_t *) packet->data; std::string_view payload {(char *) packet->data + sizeof(type), packet->dataLength - sizeof(type)}; + const auto encrypted_control_packet = type == packetTypes[IDX_ENCRYPTED]; + const auto encrypted_count = encrypted_control_packet ? session->stream_diag.control_encrypted_packets_received.fetch_add(1) + 1 : + session->stream_diag.control_encrypted_packets_received.load(); + BOOST_LOG(info) << "STREAM_DIAG control packet received" + << " launch_session_id="sv << session->launch_session_id + << " remote="sv << event_addr << ':' << event_port + << " bytes="sv << event.packet->dataLength + << " type="sv << util::hex(type).to_string_view() + << " encrypted_control_packet="sv << encrypted_control_packet + << " control_encrypted_packets_received="sv << encrypted_count + << " connect_data_zero_fallback_used="sv << session->stream_diag.control_connect_data_zero_fallback_used.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load(); call(type, session, payload, false); } @@ -1472,6 +1560,10 @@ namespace stream { << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() << " control_connect_probe_attempted="sv << session->stream_diag.control_connect_probe_attempted.load() << " control_connect_probe_peer_created="sv << session->stream_diag.control_connect_probe_peer_created.load() + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " control_connect_data_zero_fallback_used="sv << session->stream_diag.control_connect_data_zero_fallback_used.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() << " audio_raised_alone_blocks_video_or_control=0"; stream_diag_log_ready_state("ready state at control ping timeout", session, "CONTROL"sv); @@ -2666,6 +2758,7 @@ namespace stream { << " experimental_video_peer_mode="sv << stream_diag_video_peer_mode() << " experimental_reuse_audio_peer="sv << stream_diag_reuse_audio_peer_enabled() << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() << " audio_and_video_waiters_independent=1" << " audio_raised_alone_blocks_video_or_control=0"; From e6e2d048fea61f00246725c764694e49f4d6c904 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 19:48:51 -0400 Subject: [PATCH 10/21] Ignore unmapped control disconnect diagnostics --- src/stream.cpp | 53 +++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 44 insertions(+), 9 deletions(-) diff --git a/src/stream.cpp b/src/stream.cpp index 5c7f3f6efca..0dbff9d33db 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -832,11 +832,18 @@ namespace stream { // for other communications to the client. This is necessary to ensure // proper routing on multi-homed hosts. auto local_address = platf::from_sockaddr((sockaddr *) &peer->localAddress.address); - try { - session_p->localAddress = boost::asio::ip::make_address(local_address); - } catch (const boost::system::system_error &e) { - BOOST_LOG(error) << "boost::system::system_error in address parsing: " << e.what() << " (code: " << e.code() << ")"sv; - throw; + boost::system::error_code local_address_ec; + auto parsed_local_address = boost::asio::ip::make_address(local_address, local_address_ec); + if (local_address_ec) { + BOOST_LOG(warning) << "STREAM_DIAG control local address parse failed" + << " launch_session_id="sv << session_p->launch_session_id + << " local_address="sv << local_address + << " remote="sv << peer_addr << ':' << peer_port + << " expected_peer_address="sv << session_p->control.expected_peer_address + << " error="sv << local_address_ec.message() + << " continuing_with_existing_local_address=1"; + } else { + session_p->localAddress = parsed_local_address; } BOOST_LOG(debug) << "Control local address ["sv << local_address << ']'; @@ -1004,10 +1011,38 @@ namespace stream { << " bytes="sv << (event.packet ? event.packet->dataLength : 0) << " connect_data="sv << event.data; - auto session = get_session(event.peer, event.data); - if (!session) { - BOOST_LOG(warning) << "Rejected connection from ["sv << platf::from_sockaddr((sockaddr *) &event.peer->address.address) << "]: it's not properly set up"sv; - enet_peer_disconnect_now(event.peer, 0); + session_t *session = nullptr; + if (event.type == ENET_EVENT_TYPE_DISCONNECT) { + auto ptslg = _peer_to_session.lock(); + auto it = _peer_to_session->find(event.peer); + if (it != _peer_to_session->end()) { + session = it->second; + } else { + BOOST_LOG(warning) << "STREAM_DIAG control disconnect ignored" + << " reason=unmapped_peer" + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << event_addr << ':' << event_port + << " connect_data="sv << event.data + << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " fallback_attempted=0"; + + return; + } + } else if (event.type == ENET_EVENT_TYPE_CONNECT || event.type == ENET_EVENT_TYPE_RECEIVE) { + session = get_session(event.peer, event.data); + if (!session) { + BOOST_LOG(warning) << "Rejected connection from ["sv << platf::from_sockaddr((sockaddr *) &event.peer->address.address) << "]: it's not properly set up"sv; + enet_peer_disconnect_now(event.peer, 0); + + return; + } + } else { + BOOST_LOG(info) << "STREAM_DIAG control event ignored" + << " reason=unsupported_event_for_session_matching" + << " event="sv << event_type + << " local_port="sv << net::map_port(CONTROL_PORT) + << " remote="sv << event_addr << ':' << event_port + << " connect_data="sv << event.data; return; } From 7b6c3a49313e437cf0afde5f3e4abe4def12202c Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 20:04:03 -0400 Subject: [PATCH 11/21] Add ignore-control-timeout stream diagnostic --- src/rtsp.cpp | 56 ++++++++++++++++++++++++-- src/stream.cpp | 107 +++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 159 insertions(+), 4 deletions(-) diff --git a/src/rtsp.cpp b/src/rtsp.cpp index e853f57100c..c52ff741e91 100644 --- a/src/rtsp.cpp +++ b/src/rtsp.cpp @@ -13,6 +13,7 @@ extern "C" { #include #include #include +#include #include #include #include @@ -204,6 +205,20 @@ namespace rtsp_stream { return port ? std::to_string(*port) : ""s; } + bool rtsp_diag_no_control_setup_response_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_NO_CONTROL_SETUP_RESPONSE"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + std::string rtsp_message_to_string(PRTSP_MESSAGE msg) { std::ostringstream ss; @@ -496,6 +511,11 @@ namespace rtsp_stream { if (ec) { BOOST_LOG(error) << "RTSP: handle_read_plaintext(): Couldn't read from tcp socket: "sv << ec.message(); + BOOST_LOG(warning) << "STREAM_DIAG RTSP TCP read ended" + << " session_id="sv << (socket->session ? socket->session->id : 0) + << " error="sv << ec.message() + << " bytes="sv << bytes + << " observation=client_or_server_closed_rtsp_tcp"; boost::system::error_code ec; socket->sock.close(ec); @@ -534,6 +554,11 @@ namespace rtsp_stream { } void handle_data(msg_t &&req) { + BOOST_LOG(info) << "STREAM_DIAG RTSP TCP request dispatch" + << " session_id="sv << session->id + << " command="sv << req->message.request.command + << " target="sv << req->message.request.target + << " observation=rtsp_tcp_alive_for_request"; handle_data_fn(sock, *session, std::move(req)); } @@ -592,6 +617,8 @@ namespace rtsp_stream { } void handle_msg(tcp::socket &sock, launch_session_t &session, msg_t &&req) { + auto command = std::string {req->message.request.command ? req->message.request.command : ""}; + auto target = std::string {req->message.request.target ? req->message.request.target : ""}; auto func = _map_cmd_cb.find(req->message.request.command); if (func != std::end(_map_cmd_cb)) { func->second(this, sock, session, std::move(req)); @@ -601,6 +628,13 @@ namespace rtsp_stream { boost::system::error_code ec; sock.shutdown(boost::asio::socket_base::shutdown_type::shutdown_both, ec); + BOOST_LOG(info) << "STREAM_DIAG RTSP TCP request complete" + << " session_id="sv << session.id + << " command="sv << command + << " target="sv << target + << " server_shutdown_socket=1" + << " shutdown_error="sv << ec.message() + << " observation=rtsp_tcp_is_request_scoped"; } void handle_accept(const boost::system::error_code &ec) { @@ -1035,6 +1069,7 @@ namespace rtsp_stream { return; } + const auto no_control_setup_response = type == "control"sv && rtsp_diag_no_control_setup_response_enabled(); seqn.next = &session_option; @@ -1051,7 +1086,16 @@ namespace rtsp_stream { // Send identifiers that will be echoed in the other connections auto connect_data = std::to_string(session.control_connect_data); - if (type == "control"sv) { + if (type == "control"sv && no_control_setup_response) { + BOOST_LOG(warning) << "STREAM_DIAG RTSP SETUP control diagnostic response" + << " session_id="sv << session.id + << " stream_id="sv << stream_id + << " action=omit_X_SS_Connect_Data" + << " no_control_setup_response=1" + << " client_rtp_port="sv << rtsp_optional_port_to_string(client_port.rtp) + << " expected_connect_data="sv << session.control_connect_data + << " expected_effect=client_may_skip_control_enet"; + } else if (type == "control"sv) { payload_option.option = const_cast("X-SS-Connect-Data"); payload_option.content = connect_data.data(); } else { @@ -1059,7 +1103,9 @@ namespace rtsp_stream { payload_option.content = session.av_ping_payload.data(); } - port_option.next = &payload_option; + port_option.next = no_control_setup_response ? nullptr : &payload_option; + auto payload_option_name = payload_option.option ? payload_option.option : ""; + auto payload_option_value = payload_option.content ? payload_option.content : ""; BOOST_LOG(info) << "STREAM_DIAG RTSP SETUP parsed" << " session_id="sv << session.id @@ -1070,8 +1116,9 @@ namespace rtsp_stream { << " x_gs_client_port_source="sv << client_port.source << " client_rtp_port="sv << rtsp_optional_port_to_string(client_port.rtp) << " client_rtcp_port="sv << rtsp_optional_port_to_string(client_port.rtcp) - << " payload_option="sv << payload_option.option - << " payload_value="sv << payload_option.content; + << " no_control_setup_response="sv << no_control_setup_response + << " payload_option="sv << payload_option_name + << " payload_value="sv << payload_option_value; BOOST_LOG(info) << "STREAM_DIAG RTSP SETUP response" << " session_id="sv << session.id @@ -1082,6 +1129,7 @@ namespace rtsp_stream { << " x_gs_client_port_source="sv << client_port.source << " client_rtp_port="sv << rtsp_optional_port_to_string(client_port.rtp) << " client_rtcp_port="sv << rtsp_optional_port_to_string(client_port.rtcp) + << " no_control_setup_response="sv << no_control_setup_response << std::endl << "---BEGIN STREAM_DIAG RTSP SETUP RESPONSE---"sv << std::endl << rtsp_response_to_string(200, "OK", &seqn, {}) diff --git a/src/stream.cpp b/src/stream.cpp index 0dbff9d33db..b8c56cae082 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -168,6 +168,20 @@ namespace stream { return enabled; } + bool stream_diag_ignore_control_timeout_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_IGNORE_CONTROL_TIMEOUT"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + std::string_view stream_diag_video_peer_mode() { auto value = std::getenv("SUNSHINE_STREAM_DIAG_VIDEO_PEER_MODE"); if (value && *value) { @@ -535,6 +549,10 @@ namespace stream { std::atomic_bool control_connect_probe_peer_created {false}; std::atomic_bool control_connect_data_zero_fallback_used {false}; std::atomic_uint64_t control_encrypted_packets_received {0}; + std::atomic_bool ignore_control_timeout_active {false}; + std::atomic_bool ignore_control_timeout_expired {false}; + std::chrono::steady_clock::time_point ignore_control_timeout_until {}; + std::chrono::steady_clock::time_point ignore_control_timeout_next_log {}; } stream_diag; safe::mail_raw_t::event_t shutdown_event; @@ -569,9 +587,19 @@ namespace stream { << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() << " control_connect_data_zero_fallback_used="sv << session->stream_diag.control_connect_data_zero_fallback_used.load() << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " ignore_control_timeout="sv << stream_diag_ignore_control_timeout_enabled() + << " ignore_control_timeout_active="sv << session->stream_diag.ignore_control_timeout_active.load() + << " ignore_control_timeout_expired="sv << session->stream_diag.ignore_control_timeout_expired.load() << " audio_raised_alone_blocks_video_or_control=0"; } + bool stream_diag_video_started_or_promoted(session_t *session) { + return session->stream_diag.video_ping_ready.load() && + (session->stream_diag.video_udp_sent.load() > 0 || + session->stream_diag.audio_peer_video_promoted.load() || + session->stream_diag.rtsp_client_port_video_promoted.load()); + } + /** * First part of cipher must be struct of type control_encrypted_t * @@ -1582,6 +1610,81 @@ namespace stream { if (now > session->pingTimeout) { auto address = session->control.peer ? platf::from_sockaddr((sockaddr *) &session->control.peer->address.address) : session->control.expected_peer_address; + const auto ignore_timeout_conditions_met = + stream_diag_ignore_control_timeout_enabled() && + session->stream_diag.audio_ping_ready.load() && + stream_diag_video_started_or_promoted(session) && + !session->stream_diag.control_peer_ready.load(); + if (ignore_timeout_conditions_met) { + if (!session->stream_diag.ignore_control_timeout_active.exchange(true)) { + session->stream_diag.ignore_control_timeout_until = now + 30s; + session->stream_diag.ignore_control_timeout_next_log = now; + BOOST_LOG(warning) << "STREAM_DIAG control timeout ignored begin" + << " launch_session_id="sv << session->launch_session_id + << " reason=diagnostic_ignore_control_timeout" + << " hold_ms=30000" + << " remote="sv << address + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_udp_received="sv << session->stream_diag.audio_udp_received.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(session::state(*session)) + << " rtsp_active_sessions="sv << rtsp_stream::session_count() + << " process_running="sv << (proc::proc.running() != 0) + << " rtsp_tcp_observation=request_scoped_connections_watch_for_new_rtsp_logs"; + } + + if (now < session->stream_diag.ignore_control_timeout_until) { + if (now >= session->stream_diag.ignore_control_timeout_next_log) { + auto remaining_ms = std::chrono::duration_cast(session->stream_diag.ignore_control_timeout_until - now).count(); + BOOST_LOG(warning) << "STREAM_DIAG control timeout ignored keepalive" + << " launch_session_id="sv << session->launch_session_id + << " remaining_ms="sv << remaining_ms + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_udp_received="sv << session->stream_diag.audio_udp_received.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(session::state(*session)) + << " rtsp_active_sessions="sv << rtsp_stream::session_count() + << " process_running="sv << (proc::proc.running() != 0) + << " moonlight_rtsp_tcp_status=not_directly_observable_from_control_thread"; + session->stream_diag.ignore_control_timeout_next_log = now + 1s; + } + + session->pingTimeout = now + 1s; + } else { + session->stream_diag.ignore_control_timeout_expired.store(true); + BOOST_LOG(error) << "STREAM_DIAG control timeout ignored expired" + << " launch_session_id="sv << session->launch_session_id + << " held_ms=30000" + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_udp_received="sv << session->stream_diag.audio_udp_received.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(session::state(*session)) + << " rtsp_active_sessions="sv << rtsp_stream::session_count() + << " process_running="sv << (proc::proc.running() != 0); + } + } else if (stream_diag_ignore_control_timeout_enabled()) { + BOOST_LOG(warning) << "STREAM_DIAG control timeout ignore conditions not met" + << " launch_session_id="sv << session->launch_session_id + << " audio_ping_ready="sv << session->stream_diag.audio_ping_ready.load() + << " video_started_or_promoted="sv << stream_diag_video_started_or_promoted(session) + << " video_ping_ready="sv << session->stream_diag.video_ping_ready.load() + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_peer_video_promoted="sv << session->stream_diag.audio_peer_video_promoted.load() + << " rtsp_client_port_video_promoted="sv << session->stream_diag.rtsp_client_port_video_promoted.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load(); + } + + if (ignore_timeout_conditions_met && now < session->stream_diag.ignore_control_timeout_until) { + if (!session->control.peer) { + has_session_awaiting_peer = true; + } + ++pos; + continue; + } + BOOST_LOG(error) << "STREAM_DIAG control ping timeout" << " channel=CONTROL" << " launch_session_id="sv << session->launch_session_id @@ -1599,6 +1702,9 @@ namespace stream { << " control_connect_data_zero_fallback_used="sv << session->stream_diag.control_connect_data_zero_fallback_used.load() << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " ignore_control_timeout="sv << stream_diag_ignore_control_timeout_enabled() + << " ignore_control_timeout_active="sv << session->stream_diag.ignore_control_timeout_active.load() + << " ignore_control_timeout_expired="sv << session->stream_diag.ignore_control_timeout_expired.load() << " configured_ping_timeout_ms="sv << config::stream.ping_timeout.count() << " audio_raised_alone_blocks_video_or_control=0"; stream_diag_log_ready_state("ready state at control ping timeout", session, "CONTROL"sv); @@ -2794,6 +2900,7 @@ namespace stream { << " experimental_reuse_audio_peer="sv << stream_diag_reuse_audio_peer_enabled() << " experimental_control_connect_client="sv << stream_diag_control_connect_client_enabled() << " accept_control_connect_data_zero="sv << stream_diag_accept_control_connect_data_zero_enabled() + << " ignore_control_timeout="sv << stream_diag_ignore_control_timeout_enabled() << " audio_and_video_waiters_independent=1" << " audio_raised_alone_blocks_video_or_control=0"; From d41cf4db5a0f5e6cb5695803a74c64e650d71cd5 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 20:16:13 -0400 Subject: [PATCH 12/21] Add ANNOUNCE readiness diagnostics --- src/rtsp.cpp | 128 ++++++++++++++++++++++++++++++++++++++++++++++++- src/stream.cpp | 71 +++++++++++++++++++++++++++ src/stream.h | 19 ++++++++ 3 files changed, 217 insertions(+), 1 deletion(-) diff --git a/src/rtsp.cpp b/src/rtsp.cpp index c52ff741e91..f6186366dd6 100644 --- a/src/rtsp.cpp +++ b/src/rtsp.cpp @@ -11,6 +11,7 @@ extern "C" { // standard includes #include +#include #include #include #include @@ -19,6 +20,7 @@ extern "C" { #include #include #include +#include #include #include @@ -219,6 +221,53 @@ namespace rtsp_stream { return enabled; } + bool rtsp_diag_ignore_control_timeout_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_IGNORE_CONTROL_TIMEOUT"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + + bool rtsp_diag_force_announce_success_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_FORCE_ANNOUNCE_SUCCESS"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + + void rtsp_log_announce_session_state(std::string_view marker, std::uint32_t session_id, const std::shared_ptr &stream_session, std::string_view return_condition, std::chrono::steady_clock::time_point announce_start) { + const auto snapshot = stream::session::diag_snapshot(*stream_session); + const auto duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - announce_start); + BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE "sv << marker + << " session_id="sv << session_id + << " duration_ms="sv << duration.count() + << " return_condition="sv << return_condition + << " session_state="sv << static_cast(snapshot.state) + << " audio_ping_ready="sv << snapshot.audio_ping_ready + << " video_ping_ready="sv << snapshot.video_ping_ready + << " control_peer_ready="sv << snapshot.control_peer_ready + << " video_started_or_promoted="sv << snapshot.video_started_or_promoted + << " audio_peer_video_promoted="sv << snapshot.audio_peer_video_promoted + << " rtsp_client_port_video_promoted="sv << snapshot.rtsp_client_port_video_promoted + << " video_udp_sent="sv << snapshot.video_udp_sent + << " audio_udp_received="sv << snapshot.audio_udp_received + << " control_encrypted_packets_received="sv << snapshot.control_encrypted_packets_received; + } + std::string rtsp_message_to_string(PRTSP_MESSAGE msg) { std::ostringstream ss; @@ -1139,6 +1188,7 @@ namespace rtsp_stream { } void cmd_announce(rtsp_server_t *server, tcp::socket &sock, launch_session_t &session, msg_t &&req) { + const auto announce_start = std::chrono::steady_clock::now(); OPTION_ITEM option {}; // I know these string literals will not be modified @@ -1148,6 +1198,12 @@ namespace rtsp_stream { option.content = const_cast(seqn_str.c_str()); std::string_view payload {req->payload, (size_t) req->payloadLength}; + BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE begin" + << " session_id="sv << session.id + << " sequence="sv << req->sequenceNumber + << " payload_bytes="sv << payload.size() + << " ignore_control_timeout="sv << rtsp_diag_ignore_control_timeout_enabled() + << " force_announce_success="sv << rtsp_diag_force_announce_success_enabled(); std::vector lines; @@ -1353,15 +1409,85 @@ namespace rtsp_stream { auto stream_session = stream::session::alloc(config, session); server->insert(stream_session); - if (stream::session::start(*stream_session, sock.remote_endpoint().address().to_string())) { + auto remote_address = sock.remote_endpoint().address().to_string(); + auto start_call_begin = std::chrono::steady_clock::now(); + BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE calling stream session start" + << " session_id="sv << session.id + << " remote_address="sv << remote_address + << " ignore_control_timeout="sv << rtsp_diag_ignore_control_timeout_enabled() + << " force_announce_success="sv << rtsp_diag_force_announce_success_enabled(); + + auto start_result = stream::session::start(*stream_session, remote_address); + auto start_call_duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - start_call_begin); + BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE stream session start returned" + << " session_id="sv << session.id + << " result="sv << start_result + << " duration_ms="sv << start_call_duration.count(); + rtsp_log_announce_session_state("state after stream start", session.id, stream_session, start_result ? "stream_session_start_failed"sv : "stream_session_start_ok"sv, announce_start); + + if (start_result) { BOOST_LOG(error) << "Failed to start a streaming session"sv; + rtsp_log_announce_session_state("returning failure", session.id, stream_session, "stream_session_start_failed"sv, announce_start); server->remove(stream_session); respond(sock, session, &option, 500, "Internal Server Error", req->sequenceNumber, {}); return; } + auto return_condition = "normal_success_after_stream_session_start"sv; + if (rtsp_diag_force_announce_success_enabled()) { + stream::session::diag_force_announce_success_hold(*stream_session); + return_condition = "force_announce_success_immediate"sv; + BOOST_LOG(warning) << "STREAM_DIAG force announce success returning immediately" + << " session_id="sv << session.id + << " duration_ms="sv << std::chrono::duration_cast(std::chrono::steady_clock::now() - announce_start).count() + << " hold_ms=30000"; + } else if (rtsp_diag_ignore_control_timeout_enabled()) { + BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE readiness wait begin" + << " session_id="sv << session.id + << " wait_condition=audio_ready_and_video_started_or_control_ready" + << " max_wait_ms=3000" + << " control_required=0"; + auto wait_begin = std::chrono::steady_clock::now(); + auto wait_deadline = wait_begin + 3s; + stream::session::diag_snapshot_t snapshot {}; + while (std::chrono::steady_clock::now() < wait_deadline) { + snapshot = stream::session::diag_snapshot(*stream_session); + if (snapshot.control_peer_ready || + (snapshot.audio_ping_ready && snapshot.video_started_or_promoted)) { + break; + } + std::this_thread::sleep_for(50ms); + } + + snapshot = stream::session::diag_snapshot(*stream_session); + auto wait_duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - wait_begin); + BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE readiness wait end" + << " session_id="sv << session.id + << " duration_ms="sv << wait_duration.count() + << " audio_ping_ready="sv << snapshot.audio_ping_ready + << " video_started_or_promoted="sv << snapshot.video_started_or_promoted + << " control_peer_ready="sv << snapshot.control_peer_ready + << " video_udp_sent="sv << snapshot.video_udp_sent + << " control_encrypted_packets_received="sv << snapshot.control_encrypted_packets_received; + + if (!snapshot.control_peer_ready && snapshot.audio_ping_ready && snapshot.video_started_or_promoted) { + return_condition = "ignore_control_timeout_audio_video_ready"sv; + BOOST_LOG(warning) << "STREAM_DIAG announce returning early due to ignore_control_timeout" + << " session_id="sv << session.id + << " audio_ping_ready="sv << snapshot.audio_ping_ready + << " video_started_or_promoted="sv << snapshot.video_started_or_promoted + << " control_peer_ready="sv << snapshot.control_peer_ready; + } else if (snapshot.control_peer_ready) { + return_condition = "control_ready"sv; + } else { + return_condition = "ignore_control_timeout_wait_elapsed"sv; + } + } + + rtsp_log_announce_session_state("returning response", session.id, stream_session, return_condition, announce_start); respond(sock, session, &option, 200, "OK", req->sequenceNumber, {}); + rtsp_log_announce_session_state("response sent", session.id, stream_session, return_condition, announce_start); } void cmd_play(rtsp_server_t *server, tcp::socket &sock, launch_session_t &session, msg_t &&req) { diff --git a/src/stream.cpp b/src/stream.cpp index b8c56cae082..9ae983f5aa6 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -553,6 +553,10 @@ namespace stream { std::atomic_bool ignore_control_timeout_expired {false}; std::chrono::steady_clock::time_point ignore_control_timeout_until {}; std::chrono::steady_clock::time_point ignore_control_timeout_next_log {}; + std::atomic_bool force_announce_success_active {false}; + std::atomic_bool force_announce_success_expired {false}; + std::chrono::steady_clock::time_point force_announce_success_until {}; + std::chrono::steady_clock::time_point force_announce_success_next_log {}; } stream_diag; safe::mail_raw_t::event_t shutdown_event; @@ -590,6 +594,8 @@ namespace stream { << " ignore_control_timeout="sv << stream_diag_ignore_control_timeout_enabled() << " ignore_control_timeout_active="sv << session->stream_diag.ignore_control_timeout_active.load() << " ignore_control_timeout_expired="sv << session->stream_diag.ignore_control_timeout_expired.load() + << " force_announce_success_active="sv << session->stream_diag.force_announce_success_active.load() + << " force_announce_success_expired="sv << session->stream_diag.force_announce_success_expired.load() << " audio_raised_alone_blocks_video_or_control=0"; } @@ -1608,6 +1614,39 @@ namespace stream { auto session = *pos; + if (session->stream_diag.force_announce_success_active.load() && + !session->stream_diag.control_peer_ready.load()) { + if (now < session->stream_diag.force_announce_success_until) { + if (now >= session->stream_diag.force_announce_success_next_log) { + auto remaining_ms = std::chrono::duration_cast(session->stream_diag.force_announce_success_until - now).count(); + BOOST_LOG(warning) << "STREAM_DIAG force announce success keepalive" + << " launch_session_id="sv << session->launch_session_id + << " remaining_ms="sv << remaining_ms + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_udp_received="sv << session->stream_diag.audio_udp_received.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(session::state(*session)) + << " rtsp_active_sessions="sv << rtsp_stream::session_count() + << " process_running="sv << (proc::proc.running() != 0); + session->stream_diag.force_announce_success_next_log = now + 1s; + } + + session->pingTimeout = now + 1s; + } else if (!session->stream_diag.force_announce_success_expired.exchange(true)) { + BOOST_LOG(error) << "STREAM_DIAG force announce success expired" + << " launch_session_id="sv << session->launch_session_id + << " held_ms=30000" + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " audio_udp_received="sv << session->stream_diag.audio_udp_received.load() + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(session::state(*session)) + << " rtsp_active_sessions="sv << rtsp_stream::session_count() + << " process_running="sv << (proc::proc.running() != 0); + } + } + if (now > session->pingTimeout) { auto address = session->control.peer ? platf::from_sockaddr((sockaddr *) &session->control.peer->address.address) : session->control.expected_peer_address; const auto ignore_timeout_conditions_met = @@ -2815,6 +2854,38 @@ namespace stream { return session.state.load(std::memory_order_relaxed); } + diag_snapshot_t diag_snapshot(session_t &session) { + return { + session.state.load(std::memory_order_relaxed), + session.stream_diag.audio_ping_ready.load(), + session.stream_diag.video_ping_ready.load(), + session.stream_diag.control_peer_ready.load(), + stream_diag_video_started_or_promoted(&session), + session.stream_diag.audio_peer_video_promoted.load(), + session.stream_diag.rtsp_client_port_video_promoted.load(), + session.stream_diag.video_udp_sent.load(), + session.stream_diag.audio_udp_received.load(), + session.stream_diag.control_encrypted_packets_received.load(), + }; + } + + void diag_force_announce_success_hold(session_t &session) { + auto now = std::chrono::steady_clock::now(); + session.stream_diag.force_announce_success_active.store(true); + session.stream_diag.force_announce_success_expired.store(false); + session.stream_diag.force_announce_success_until = now + 30s; + session.stream_diag.force_announce_success_next_log = now; + session.pingTimeout = now + 1s; + BOOST_LOG(warning) << "STREAM_DIAG force announce success hold armed" + << " launch_session_id="sv << session.launch_session_id + << " hold_ms=30000" + << " video_udp_sent="sv << session.stream_diag.video_udp_sent.load() + << " audio_udp_received="sv << session.stream_diag.audio_udp_received.load() + << " control_peer_ready="sv << session.stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session.stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(state(session)); + } + void stop(session_t &session) { while_starting_do_nothing(session.state); auto expected = state_e::RUNNING; diff --git a/src/stream.h b/src/stream.h index 53afff4fabe..2c9a563b8fe 100644 --- a/src/stream.h +++ b/src/stream.h @@ -5,6 +5,10 @@ #pragma once // standard includes +#include +#include +#include +#include #include // lib includes @@ -46,10 +50,25 @@ namespace stream { RUNNING, ///< The session is running }; + struct diag_snapshot_t { + state_e state; + bool audio_ping_ready; + bool video_ping_ready; + bool control_peer_ready; + bool video_started_or_promoted; + bool audio_peer_video_promoted; + bool rtsp_client_port_video_promoted; + std::uint64_t video_udp_sent; + std::uint64_t audio_udp_received; + std::uint64_t control_encrypted_packets_received; + }; + std::shared_ptr alloc(config_t &config, rtsp_stream::launch_session_t &launch_session); int start(session_t &session, const std::string &addr_string); void stop(session_t &session); void join(session_t &session); state_e state(session_t &session); + diag_snapshot_t diag_snapshot(session_t &session); + void diag_force_announce_success_hold(session_t &session); } // namespace session } // namespace stream From 9873f04a96d9fbbb5673285e7458af15911ecb12 Mon Sep 17 00:00:00 2001 From: Codex Date: Mon, 11 May 2026 20:29:00 -0400 Subject: [PATCH 13/21] Add true immediate ANNOUNCE diagnostic --- src/rtsp.cpp | 62 ++++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 60 insertions(+), 2 deletions(-) diff --git a/src/rtsp.cpp b/src/rtsp.cpp index f6186366dd6..9774c791f5d 100644 --- a/src/rtsp.cpp +++ b/src/rtsp.cpp @@ -249,6 +249,20 @@ namespace rtsp_stream { return enabled; } + bool rtsp_diag_force_announce_success_immediate_enabled() { + static const bool enabled = []() { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_FORCE_ANNOUNCE_SUCCESS_IMMEDIATE"); + if (!value) { + return false; + } + + std::string_view text {value}; + return text == "1"sv || text == "true"sv || text == "TRUE"sv || text == "yes"sv || text == "on"sv; + }(); + + return enabled; + } + void rtsp_log_announce_session_state(std::string_view marker, std::uint32_t session_id, const std::shared_ptr &stream_session, std::string_view return_condition, std::chrono::steady_clock::time_point announce_start) { const auto snapshot = stream::session::diag_snapshot(*stream_session); const auto duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - announce_start); @@ -1203,7 +1217,8 @@ namespace rtsp_stream { << " sequence="sv << req->sequenceNumber << " payload_bytes="sv << payload.size() << " ignore_control_timeout="sv << rtsp_diag_ignore_control_timeout_enabled() - << " force_announce_success="sv << rtsp_diag_force_announce_success_enabled(); + << " force_announce_success="sv << rtsp_diag_force_announce_success_enabled() + << " force_announce_success_immediate="sv << rtsp_diag_force_announce_success_immediate_enabled(); std::vector lines; @@ -1410,12 +1425,55 @@ namespace rtsp_stream { server->insert(stream_session); auto remote_address = sock.remote_endpoint().address().to_string(); + if (rtsp_diag_force_announce_success_immediate_enabled()) { + stream::session::diag_force_announce_success_hold(*stream_session); + rtsp_log_announce_session_state("true immediate prepared", session.id, stream_session, "force_announce_success_immediate_pre_start"sv, announce_start); + + std::thread { + [server, stream_session, remote_address, session_id = session.id, announce_start]() { + platf::set_thread_name("rtsp::diagAnnounceStart"); + auto start_call_begin = std::chrono::steady_clock::now(); + BOOST_LOG(warning) << "STREAM_DIAG true immediate ANNOUNCE background stream start begin" + << " session_id="sv << session_id + << " remote_address="sv << remote_address; + + auto start_result = stream::session::start(*stream_session, remote_address); + auto start_call_duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - start_call_begin); + BOOST_LOG(warning) << "STREAM_DIAG true immediate ANNOUNCE background stream start returned" + << " session_id="sv << session_id + << " result="sv << start_result + << " duration_ms="sv << start_call_duration.count(); + rtsp_log_announce_session_state("true immediate background start returned", session_id, stream_session, start_result ? "background_stream_session_start_failed"sv : "background_stream_session_start_ok"sv, announce_start); + + if (start_result) { + BOOST_LOG(error) << "STREAM_DIAG true immediate ANNOUNCE background stream start failed" + << " session_id="sv << session_id; + server->remove(stream_session); + return; + } + + stream::session::diag_force_announce_success_hold(*stream_session); + } + }.detach(); + + rtsp_log_announce_session_state("true immediate returning response", session.id, stream_session, "force_announce_success_immediate_response_before_start_return"sv, announce_start); + respond(sock, session, &option, 200, "OK", req->sequenceNumber, {}); + auto response_duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - announce_start); + BOOST_LOG(warning) << "STREAM_DIAG true immediate ANNOUNCE response sent" + << " session_id="sv << session.id + << " duration_ms="sv << response_duration.count() + << " target_duration_ms_under=500"; + rtsp_log_announce_session_state("true immediate response sent", session.id, stream_session, "force_announce_success_immediate_response_sent"sv, announce_start); + return; + } + auto start_call_begin = std::chrono::steady_clock::now(); BOOST_LOG(info) << "STREAM_DIAG ANNOUNCE calling stream session start" << " session_id="sv << session.id << " remote_address="sv << remote_address << " ignore_control_timeout="sv << rtsp_diag_ignore_control_timeout_enabled() - << " force_announce_success="sv << rtsp_diag_force_announce_success_enabled(); + << " force_announce_success="sv << rtsp_diag_force_announce_success_enabled() + << " force_announce_success_immediate="sv << rtsp_diag_force_announce_success_immediate_enabled(); auto start_result = stream::session::start(*stream_session, remote_address); auto start_call_duration = std::chrono::duration_cast(std::chrono::steady_clock::now() - start_call_begin); From c0f21f1f1b5b4452ce672d397542d32a12e5ca36 Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 12 May 2026 00:08:27 -0400 Subject: [PATCH 14/21] Add stream video test pattern diagnostics --- src/platform/linux/kmsgrab.cpp | 48 +++++++ src/stream.cpp | 29 ++++ src/video.cpp | 240 ++++++++++++++++++++++++++++++++- src/video.h | 25 ++++ 4 files changed, 338 insertions(+), 4 deletions(-) diff --git a/src/platform/linux/kmsgrab.cpp b/src/platform/linux/kmsgrab.cpp index 11571c7c361..dc79bacbdef 100644 --- a/src/platform/linux/kmsgrab.cpp +++ b/src/platform/linux/kmsgrab.cpp @@ -244,6 +244,11 @@ namespace platf { return DRM_MODE_CONNECTOR_Unknown; } + std::string connector_name(std::uint32_t type, std::uint32_t index) { + auto name = drmModeGetConnectorTypeName(type); + return std::string {name ? name : "UNKNOWN"} + "-" + std::to_string(index); + } + class plane_it_t: public round_robin_util::it_wrap_t { public: plane_it_t(int fd, std::uint32_t *plane_p, std::uint32_t *end): @@ -758,6 +763,11 @@ namespace platf { plane_id = plane->plane_id; crtc_id = plane->crtc_id; crtc_index = card.get_crtc_index_by_id(plane->crtc_id); + card_path = entry.path().generic_string(); + + auto plane_props = card.plane_props(plane->plane_id); + auto plane_type_value = card.prop_value_by_name(plane_props, "type"sv); + plane_type_name = std::string {kms::plane_type(plane_type_value.value_or(0))}; // Find the connector for this CRTC kms::conn_type_count_t conn_type_count; @@ -766,12 +776,28 @@ namespace platf { BOOST_LOG(info) << "Found connector ID ["sv << connector.connector_id << ']'; connector_id = connector.connector_id; + connector_name = kms::connector_name(connector.type, connector.index); auto connector_props = card.connector_props(*connector_id); hdr_metadata_blob_id = card.prop_value_by_name(connector_props, "HDR_OUTPUT_METADATA"sv); } } + BOOST_LOG(info) << "STREAM_DIAG kms capture selected" + << " drm_device="sv << card_path + << " connector="sv << (connector_name.empty() ? "unknown" : connector_name) + << " connector_id="sv << (connector_id ? std::to_string(*connector_id) : std::string {""}) + << " crtc_id="sv << crtc_id + << " crtc_index="sv << crtc_index + << " plane_id="sv << plane_id + << " plane_type="sv << plane_type_name + << " framebuffer_id="sv << fb->fb_id + << " width="sv << fb->width + << " height="sv << fb->height + << " pixel_format="sv << util::view(fb->pixel_format) + << " modifier="sv << fb->modifier + << " pitch0="sv << fb->pitches[0]; + this->card = std::move(card); goto break_loop; } @@ -1121,6 +1147,24 @@ namespace platf { sd->modifier = fb->modifier; sd->fourcc = fb->pixel_format; + if (stream_diag_kms_frames_logged < 60) { + ++stream_diag_kms_frames_logged; + BOOST_LOG(info) << "STREAM_DIAG kms frame" + << " frame="sv << stream_diag_kms_frames_logged + << " drm_device="sv << card_path + << " connector="sv << (connector_name.empty() ? "unknown" : connector_name) + << " connector_id="sv << (connector_id ? std::to_string(*connector_id) : std::string {""}) + << " crtc_id="sv << crtc_id + << " plane_id="sv << plane_id + << " plane_type="sv << plane_type_name + << " framebuffer_id="sv << fb->fb_id + << " width="sv << fb->width + << " height="sv << fb->height + << " pixel_format="sv << util::view(fb->pixel_format) + << " modifier="sv << fb->modifier + << " pitch0="sv << fb->pitches[0]; + } + if ( fb->width != img_width || fb->height != img_height @@ -1145,6 +1189,10 @@ namespace platf { int plane_id; int crtc_id; int crtc_index; + std::string card_path; + std::string connector_name; + std::string plane_type_name; + std::uint64_t stream_diag_kms_frames_logged = 0; std::optional connector_id; std::optional hdr_metadata_blob_id; diff --git a/src/stream.cpp b/src/stream.cpp index 9ae983f5aa6..d73694e4ddb 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -557,6 +557,7 @@ namespace stream { std::atomic_bool force_announce_success_expired {false}; std::chrono::steady_clock::time_point force_announce_success_until {}; std::chrono::steady_clock::time_point force_announce_success_next_log {}; + std::chrono::steady_clock::time_point video_summary_next_log {}; } stream_diag; safe::mail_raw_t::event_t shutdown_event; @@ -606,6 +607,33 @@ namespace stream { session->stream_diag.rtsp_client_port_video_promoted.load()); } + void stream_diag_log_video_summary(session_t *session, std::chrono::steady_clock::time_point now) { + if (now < session->stream_diag.video_summary_next_log) { + return; + } + + auto frame_stats = video::stream_diag_snapshot(session); + BOOST_LOG(info) << "STREAM_DIAG video summary" + << " launch_session_id="sv << session->launch_session_id + << " video_udp_sent="sv << session->stream_diag.video_udp_sent.load() + << " encoded_frames="sv << frame_stats.encoded_frames + << " capture_frames="sv << frame_stats.capture_frames + << " latest_frame_valid="sv << frame_stats.valid + << " latest_frame_width="sv << frame_stats.width + << " latest_frame_height="sv << frame_stats.height + << " latest_frame_avg_luma="sv << frame_stats.avg_luma + << " latest_frame_min="sv << frame_stats.min_sample + << " latest_frame_max="sv << frame_stats.max_sample + << " latest_frame_nonblack="sv << frame_stats.nonblack_samples + << " latest_frame_total_samples="sv << frame_stats.total_samples + << " latest_frame_all_black="sv << frame_stats.all_black + << " latest_frame_nearly_static="sv << frame_stats.nearly_static + << " control_peer_ready="sv << session->stream_diag.control_peer_ready.load() + << " control_encrypted_packets_received="sv << session->stream_diag.control_encrypted_packets_received.load() + << " session_state="sv << static_cast(session::state(*session)); + session->stream_diag.video_summary_next_log = now + 1s; + } + /** * First part of cipher must be struct of type control_encrypted_t * @@ -1613,6 +1641,7 @@ namespace stream { } auto session = *pos; + stream_diag_log_video_summary(session, now); if (session->stream_diag.force_announce_success_active.load() && !session->stream_diag.control_peer_ready.load()) { diff --git a/src/video.cpp b/src/video.cpp index 00af66c3a69..8724e37ebd6 100644 --- a/src/video.cpp +++ b/src/video.cpp @@ -5,9 +5,14 @@ // standard includes #include #include +#include #include +#include +#include #include +#include #include +#include // lib includes #include @@ -42,6 +47,211 @@ using namespace std::literals; namespace video { namespace { + std::mutex stream_diag_frame_stats_mutex; + std::unordered_map stream_diag_frame_stats_by_channel; + + bool stream_diag_test_pattern_enabled() { + static const bool enabled = [] { + auto value = std::getenv("SUNSHINE_STREAM_DIAG_TEST_PATTERN"); + if (!value) { + return false; + } + std::string_view flag {value}; + return flag != "0"sv && flag != "false"sv && flag != "FALSE"sv; + }(); + return enabled; + } + + std::string_view stream_diag_img_format(const platf::img_t &img) { + if (img.pixel_pitch == 4) { + return "BGR0/BGRA-assumed"sv; + } + if (img.pixel_pitch == 3) { + return "BGR-assumed"sv; + } + return "unknown"sv; + } + + stream_diag_frame_stats_t stream_diag_sample_frame(const platf::img_t &img) { + stream_diag_frame_stats_t stats {}; + stats.width = img.width; + stats.height = img.height; + stats.pixel_pitch = img.pixel_pitch; + stats.row_pitch = img.row_pitch; + + if (!img.data || img.width <= 0 || img.height <= 0 || img.pixel_pitch < 3) { + return stats; + } + + const auto row_pitch = img.row_pitch > 0 ? img.row_pitch : img.width * img.pixel_pitch; + const int samples_x = std::min(img.width, 16); + const int samples_y = std::min(img.height, 16); + if (samples_x <= 0 || samples_y <= 0) { + return stats; + } + + std::uint64_t sum_r = 0; + std::uint64_t sum_g = 0; + std::uint64_t sum_b = 0; + int min_sample = 255; + int max_sample = 0; + std::uint64_t nonblack = 0; + std::uint64_t total = 0; + + for (int sy = 0; sy < samples_y; ++sy) { + const auto y = ((sy * 2 + 1) * img.height) / (samples_y * 2); + const auto *row = img.data + (static_cast(y) * row_pitch); + for (int sx = 0; sx < samples_x; ++sx) { + const auto x = ((sx * 2 + 1) * img.width) / (samples_x * 2); + const auto *pixel = row + (static_cast(x) * img.pixel_pitch); + const int b = pixel[0]; + const int g = pixel[1]; + const int r = pixel[2]; + + sum_r += r; + sum_g += g; + sum_b += b; + min_sample = std::min({min_sample, r, g, b}); + max_sample = std::max({max_sample, r, g, b}); + if (r > 8 || g > 8 || b > 8) { + ++nonblack; + } + ++total; + } + } + + if (total == 0) { + return stats; + } + + stats.valid = true; + stats.avg_r = static_cast(sum_r) / static_cast(total); + stats.avg_g = static_cast(sum_g) / static_cast(total); + stats.avg_b = static_cast(sum_b) / static_cast(total); + stats.avg_luma = (0.2126 * stats.avg_r) + (0.7152 * stats.avg_g) + (0.0722 * stats.avg_b); + stats.min_sample = min_sample; + stats.max_sample = max_sample; + stats.nonblack_samples = nonblack; + stats.total_samples = total; + stats.all_black = nonblack == 0 || max_sample <= 8; + + return stats; + } + + void stream_diag_note_captured_frame(void *channel_data, const platf::img_t &img) { + if (!channel_data) { + return; + } + + std::scoped_lock lock {stream_diag_frame_stats_mutex}; + auto &stats = stream_diag_frame_stats_by_channel[channel_data]; + const auto previous = stats; + auto sampled = stream_diag_sample_frame(img); + + sampled.capture_frames = previous.capture_frames + 1; + sampled.encoded_frames = previous.encoded_frames; + if (sampled.valid && previous.valid) { + sampled.nearly_static = + std::abs(sampled.avg_luma - previous.avg_luma) < 0.5 && + sampled.min_sample == previous.min_sample && + sampled.max_sample == previous.max_sample && + sampled.nonblack_samples == previous.nonblack_samples; + } + + stats = sampled; + + if (stats.capture_frames <= 60) { + BOOST_LOG(info) << "STREAM_DIAG capture frame="sv << stats.capture_frames + << " width="sv << stats.width + << " height="sv << stats.height + << " format="sv << stream_diag_img_format(img) + << " pixel_pitch="sv << stats.pixel_pitch + << " row_pitch="sv << stats.row_pitch + << " avg_luma="sv << stats.avg_luma + << " avg_rgb="sv << stats.avg_r << ',' << stats.avg_g << ',' << stats.avg_b + << " min="sv << stats.min_sample + << " max="sv << stats.max_sample + << " nonblack="sv << stats.nonblack_samples + << " total_samples="sv << stats.total_samples + << " all_black="sv << stats.all_black + << " nearly_static="sv << stats.nearly_static; + } + } + + void stream_diag_note_encoded_frame(void *channel_data) { + if (!channel_data) { + return; + } + + std::scoped_lock lock {stream_diag_frame_stats_mutex}; + ++stream_diag_frame_stats_by_channel[channel_data].encoded_frames; + } + + void stream_diag_apply_test_pattern(platf::img_t &img, int64_t frame_nr) { + if (!stream_diag_test_pattern_enabled()) { + return; + } + + static std::atomic_bool logged_enabled {false}; + if (!logged_enabled.exchange(true)) { + BOOST_LOG(warning) << "STREAM_DIAG test pattern enabled"sv; + } + + if (!img.data || img.width <= 0 || img.height <= 0 || img.pixel_pitch < 3) { + BOOST_LOG(warning) << "STREAM_DIAG test pattern skipped" + << " frame="sv << frame_nr + << " reason=no_cpu_image_data" + << " width="sv << img.width + << " height="sv << img.height + << " pixel_pitch="sv << img.pixel_pitch + << " row_pitch="sv << img.row_pitch; + return; + } + + static constexpr std::array, 8> colors {{ + {{255, 32, 32}}, + {{255, 180, 32}}, + {{255, 255, 32}}, + {{32, 255, 64}}, + {{32, 220, 255}}, + {{32, 64, 255}}, + {{180, 32, 255}}, + {{255, 32, 180}}, + }}; + + const auto row_pitch = img.row_pitch > 0 ? img.row_pitch : img.width * img.pixel_pitch; + const int phase = static_cast((frame_nr * 11) % std::max(1, img.width)); + + for (int y = 0; y < img.height; ++y) { + auto *row = img.data + (static_cast(y) * row_pitch); + for (int x = 0; x < img.width; ++x) { + const int shifted_x = (x + phase) % std::max(1, img.width); + const int bar = (shifted_x * static_cast(colors.size())) / std::max(1, img.width); + const bool checker = (((x + phase) / 96) ^ (y / 96) ^ static_cast(frame_nr / 8)) & 1; + const auto &rgb = colors[bar % colors.size()]; + auto *pixel = row + (static_cast(x) * img.pixel_pitch); + + const auto scale = checker ? 255 : 128; + const auto r = static_cast((rgb[0] * scale) / 255); + const auto g = static_cast((rgb[1] * scale) / 255); + const auto b = static_cast((rgb[2] * scale) / 255); + + pixel[0] = b; + pixel[1] = g; + pixel[2] = r; + if (img.pixel_pitch > 3) { + pixel[3] = 255; + } + } + } + + if (frame_nr <= 60 || frame_nr % 120 == 0) { + BOOST_LOG(info) << "STREAM_DIAG test pattern frame="sv << frame_nr + << " width="sv << img.width + << " height="sv << img.height; + } + } + /** * @brief Check if we can allow probing for the encoders. * @return True if there should be no issues with the probing, false if we should prevent it. @@ -72,6 +282,20 @@ namespace video { } } // namespace + stream_diag_frame_stats_t stream_diag_snapshot(void *channel_data) { + if (!channel_data) { + return {}; + } + + std::scoped_lock lock {stream_diag_frame_stats_mutex}; + auto it = stream_diag_frame_stats_by_channel.find(channel_data); + if (it == std::end(stream_diag_frame_stats_by_channel)) { + return {}; + } + + return it->second; + } + void free_ctx(AVCodecContext *ctx) { avcodec_free_context(&ctx); } @@ -2104,6 +2328,8 @@ namespace video { if (!requested_idr_frame || images->peek()) { if (auto img = images->pop(max_frametime)) { frame_timestamp = img->frame_timestamp; + stream_diag_note_captured_frame(channel_data, *img); + stream_diag_apply_test_pattern(*img, frame_nr); if (session->convert(*img)) { BOOST_LOG(error) << "Could not convert image"sv; return; @@ -2117,6 +2343,7 @@ namespace video { BOOST_LOG(error) << "Could not encode video packet"sv; return; } + stream_diag_note_encoded_frame(channel_data); session->request_normal_frame(); @@ -2361,11 +2588,15 @@ namespace video { ctx->idr_events->pop(); } - if (frame_captured && pos->session->convert(*img)) { - BOOST_LOG(error) << "Could not convert image"sv; - ctx->shutdown_event->raise(true); + if (frame_captured) { + stream_diag_note_captured_frame(ctx->channel_data, *img); + stream_diag_apply_test_pattern(*img, ctx->frame_nr); + if (pos->session->convert(*img)) { + BOOST_LOG(error) << "Could not convert image"sv; + ctx->shutdown_event->raise(true); - continue; + continue; + } } std::optional frame_timestamp; @@ -2379,6 +2610,7 @@ namespace video { continue; } + stream_diag_note_encoded_frame(ctx->channel_data); pos->session->request_normal_frame(); diff --git a/src/video.h b/src/video.h index 8fa25850036..7e180bc2e27 100644 --- a/src/video.h +++ b/src/video.h @@ -4,6 +4,9 @@ */ #pragma once +// standard includes +#include + // local includes #include "input.h" #include "platform/common.h" @@ -327,6 +330,26 @@ namespace video { using packet_t = std::unique_ptr; + struct stream_diag_frame_stats_t { + bool valid = false; + std::uint64_t capture_frames = 0; + std::uint64_t encoded_frames = 0; + int width = 0; + int height = 0; + int pixel_pitch = 0; + int row_pitch = 0; + double avg_luma = 0.0; + double avg_r = 0.0; + double avg_g = 0.0; + double avg_b = 0.0; + int min_sample = 0; + int max_sample = 0; + std::uint64_t nonblack_samples = 0; + std::uint64_t total_samples = 0; + bool all_black = false; + bool nearly_static = false; + }; + struct hdr_info_raw_t { explicit hdr_info_raw_t(bool enabled): enabled {enabled}, @@ -352,6 +375,8 @@ namespace video { void *channel_data ); + stream_diag_frame_stats_t stream_diag_snapshot(void *channel_data); + bool validate_encoder(encoder_t &encoder, bool expect_failure); /** From 1ab4f2b7d9b526a308593de36d6e4dc3a6f1ab5d Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 12 May 2026 00:45:08 -0400 Subject: [PATCH 15/21] Add KMS plane selection diagnostics --- src/platform/linux/kmsgrab.cpp | 549 +++++++++++++++++++++++++++------ 1 file changed, 451 insertions(+), 98 deletions(-) diff --git a/src/platform/linux/kmsgrab.cpp b/src/platform/linux/kmsgrab.cpp index dc79bacbdef..faaf3233a83 100644 --- a/src/platform/linux/kmsgrab.cpp +++ b/src/platform/linux/kmsgrab.cpp @@ -4,8 +4,12 @@ */ // standard includes #include +#include +#include #include #include +#include +#include #include #include @@ -333,7 +337,8 @@ namespace platf { } version_t ver {drmGetVersion(fd.el)}; - BOOST_LOG(info) << path << " -> "sv << ((ver && ver->name) ? ver->name : "UNKNOWN"); + card_name = (ver && ver->name) ? ver->name : "UNKNOWN"; + BOOST_LOG(info) << path << " -> "sv << card_name; // Open the render node for this card to share with libva. // If it fails, we'll just share the primary node instead. @@ -552,8 +557,242 @@ namespace platf { file_t fd; file_t render_fd; plane_res_t plane_res; + std::string card_name; }; + std::string env_value(const char *name) { + auto value = std::getenv(name); + return value ? value : ""; + } + + std::optional uint_env_value(const char *name) { + auto value = std::getenv(name); + if (!value || !*value) { + return std::nullopt; + } + + char *end = nullptr; + errno = 0; + auto parsed = std::strtoul(value, &end, 10); + if (errno || end == value || *end || parsed > std::numeric_limits::max()) { + BOOST_LOG(warning) << "STREAM_DIAG invalid uint env "sv << name << '=' << value; + return std::nullopt; + } + + return static_cast(parsed); + } + + struct framebuffer_sample_t { + bool attempted = false; + bool available = false; + bool all_black = false; + double avg_luma = 0.0; + double avg_r = 0.0; + double avg_g = 0.0; + double avg_b = 0.0; + int min_sample = 0; + int max_sample = 0; + std::uint64_t nonblack_samples = 0; + std::uint64_t total_samples = 0; + std::string reason = "not_attempted"; + }; + + framebuffer_sample_t sample_framebuffer(card_t &card, wrapper_fb &fb) { + framebuffer_sample_t sample; + sample.attempted = true; + + if (!fb.handles[0] || !fb.pitches[0] || !fb.width || !fb.height) { + sample.reason = "missing_handle_or_geometry"; + return sample; + } + + const auto bytes_per_pixel = fb.pitches[0] / fb.width; + if (bytes_per_pixel < 3) { + sample.reason = "unsupported_bytes_per_pixel"; + return sample; + } + + auto plane_fd = card.handleFD(fb.handles[0]); + if (plane_fd.el < 0) { + sample.reason = "handlefd_failed"; + return sample; + } + + size_t mapped_size = static_cast(fb.pitches[0]) * fb.height; + void *mapped_data = mmap(nullptr, mapped_size, PROT_READ, MAP_SHARED, plane_fd.el, fb.offsets[0]); + if (mapped_data == MAP_FAILED && errno == ENOSYS) { + drm_mode_map_dumb map = {}; + map.handle = fb.handles[0]; + if (drmIoctl(card.fd.el, DRM_IOCTL_MODE_MAP_DUMB, &map) == 0) { + mapped_data = mmap(nullptr, mapped_size, PROT_READ, MAP_SHARED, card.fd.el, map.offset); + } + } + + if (mapped_data == MAP_FAILED) { + sample.reason = std::string {"mmap_failed:"} + strerror(errno); + return sample; + } + + struct dma_buf_sync sync; + sync.flags = DMA_BUF_SYNC_START | DMA_BUF_SYNC_READ; + drmIoctl(plane_fd.el, DMA_BUF_IOCTL_SYNC, &sync); + + const int samples_x = std::min(fb.width, 16); + const int samples_y = std::min(fb.height, 16); + std::uint64_t sum_r = 0; + std::uint64_t sum_g = 0; + std::uint64_t sum_b = 0; + int min_sample = 255; + int max_sample = 0; + std::uint64_t nonblack = 0; + std::uint64_t total = 0; + + for (int sy = 0; sy < samples_y; ++sy) { + const auto y = ((sy * 2 + 1) * fb.height) / (samples_y * 2); + const auto *row = static_cast(mapped_data) + (static_cast(y) * fb.pitches[0]); + for (int sx = 0; sx < samples_x; ++sx) { + const auto x = ((sx * 2 + 1) * fb.width) / (samples_x * 2); + const auto *pixel = row + (static_cast(x) * bytes_per_pixel); + const int b = pixel[0]; + const int g = pixel[1]; + const int r = pixel[2]; + + sum_r += r; + sum_g += g; + sum_b += b; + min_sample = std::min({min_sample, r, g, b}); + max_sample = std::max({max_sample, r, g, b}); + if (r > 8 || g > 8 || b > 8) { + ++nonblack; + } + ++total; + } + } + + sync.flags = DMA_BUF_SYNC_END | DMA_BUF_SYNC_READ; + drmIoctl(plane_fd.el, DMA_BUF_IOCTL_SYNC, &sync); + munmap(mapped_data, mapped_size); + + if (!total) { + sample.reason = "no_samples"; + return sample; + } + + sample.available = true; + sample.reason = "ok"; + sample.avg_r = static_cast(sum_r) / static_cast(total); + sample.avg_g = static_cast(sum_g) / static_cast(total); + sample.avg_b = static_cast(sum_b) / static_cast(total); + sample.avg_luma = (0.2126 * sample.avg_r) + (0.7152 * sample.avg_g) + (0.0722 * sample.avg_b); + sample.min_sample = min_sample; + sample.max_sample = max_sample; + sample.nonblack_samples = nonblack; + sample.total_samples = total; + sample.all_black = nonblack == 0 || max_sample <= 8; + return sample; + } + + struct plane_candidate_t { + std::string card_path; + std::string card_filename; + std::string card_name; + std::string connector_name = "unknown"; + std::optional connector_id; + bool connector_connected = false; + std::uint32_t crtc_id = 0; + int crtc_index = -1; + std::uint32_t crtc_width = 0; + std::uint32_t crtc_height = 0; + std::uint32_t plane_id = 0; + std::string plane_type_name = "UNKNOWN"; + std::uint64_t plane_type = 0; + std::uint32_t possible_crtcs = 0; + std::uint32_t fb_id = 0; + std::uint32_t fb_width = 0; + std::uint32_t fb_height = 0; + std::uint32_t pixel_format = 0; + std::uint64_t modifier = 0; + std::uint32_t pitch0 = 0; + int monitor_index = -1; + std::optional hdr_metadata_blob_id; + framebuffer_sample_t sample; + bool skipped = true; + bool forced = false; + std::string skip_reason = "not_evaluated"; + std::int64_t score = 0; + }; + + std::int64_t score_plane_candidate(const plane_candidate_t &candidate, const ::video::config_t &config, int monitor_index) { + if (candidate.forced) { + return std::numeric_limits::max() / 4; + } + + std::int64_t score = 0; + if (candidate.connector_connected) { + score += 100; + } + if (candidate.monitor_index == monitor_index) { + score += 100; + } + if (candidate.plane_type == DRM_PLANE_TYPE_PRIMARY) { + score += 1000; + } + if (candidate.fb_width == candidate.crtc_width && candidate.fb_height == candidate.crtc_height) { + score += 5000; + } + if (candidate.fb_width == static_cast(config.width) && candidate.fb_height == static_cast(config.height)) { + score += 3000; + } + score += std::min((static_cast(candidate.fb_width) * candidate.fb_height) / 100000, 500); + + if (candidate.sample.available) { + if (candidate.sample.all_black) { + score -= 3000; + } else { + score += 1000; + } + } + + return score; + } + + void log_plane_candidate(std::string_view marker, const plane_candidate_t &candidate) { + BOOST_LOG(info) << "STREAM_DIAG "sv << marker + << " drm_device="sv << candidate.card_path + << " card_name="sv << candidate.card_name + << " connector="sv << candidate.connector_name + << " connector_id="sv << (candidate.connector_id ? std::to_string(*candidate.connector_id) : std::string {""}) + << " connector_connected="sv << candidate.connector_connected + << " crtc_id="sv << candidate.crtc_id + << " crtc_index="sv << candidate.crtc_index + << " crtc_width="sv << candidate.crtc_width + << " crtc_height="sv << candidate.crtc_height + << " plane_id="sv << candidate.plane_id + << " plane_type="sv << candidate.plane_type_name + << " fb_id="sv << candidate.fb_id + << " fb_width="sv << candidate.fb_width + << " fb_height="sv << candidate.fb_height + << " pixel_format="sv << (candidate.pixel_format ? std::string {util::view(candidate.pixel_format)} : std::string {""}) + << " modifier="sv << candidate.modifier + << " pitch0="sv << candidate.pitch0 + << " possible_crtcs="sv << candidate.possible_crtcs + << " monitor_index="sv << candidate.monitor_index + << " skipped="sv << candidate.skipped + << " skip_reason="sv << candidate.skip_reason + << " forced="sv << candidate.forced + << " score="sv << candidate.score + << " sample_attempted="sv << candidate.sample.attempted + << " sample_available="sv << candidate.sample.available + << " sample_reason="sv << candidate.sample.reason + << " sample_avg_luma="sv << candidate.sample.avg_luma + << " sample_avg_rgb="sv << candidate.sample.avg_r << ',' << candidate.sample.avg_g << ',' << candidate.sample.avg_b + << " sample_min="sv << candidate.sample.min_sample + << " sample_max="sv << candidate.sample.max_sample + << " sample_nonblack="sv << candidate.sample.nonblack_samples + << " sample_total="sv << candidate.sample.total_samples + << " sample_all_black="sv << candidate.sample.all_black; + } + std::map map_crtc_to_monitor(const std::vector &connectors) { std::map result; @@ -617,7 +856,16 @@ namespace platf { delay = std::chrono::nanoseconds {1s} / config.framerate; int monitor_index = util::from_view(display_name); - int monitor = 0; + const auto forced_connector = kms::env_value("SUNSHINE_STREAM_DIAG_KMS_FORCE_CONNECTOR"); + const auto forced_plane_id = kms::uint_env_value("SUNSHINE_STREAM_DIAG_KMS_FORCE_PLANE_ID"); + if (!forced_connector.empty()) { + BOOST_LOG(warning) << "STREAM_DIAG KMS force connector enabled connector="sv << forced_connector; + } + if (forced_plane_id) { + BOOST_LOG(warning) << "STREAM_DIAG KMS force plane enabled plane_id="sv << *forced_plane_id; + } + + std::optional best_candidate; fs::path card_dir {"/dev/dri"sv}; for (auto &entry : fs::directory_iterator {card_dir}) { @@ -650,33 +898,83 @@ namespace platf { continue; } + // We need to find the correct /dev/dri/card{nr} to correlate the crtc_id with the monitor descriptor. + auto card_descriptor_pos = std::find_if(std::begin(card_descriptors), std::end(card_descriptors), [&](card_descriptor_t &cd) { + return cd.path == filestring; + }); + + kms::conn_type_count_t conn_type_count; + auto connectors = card.monitors(conn_type_count); + int plane_monitor = 0; + auto end = std::end(card); for (auto plane = std::begin(card); plane != end; ++plane) { - // Skip unused planes - if (!plane->fb_id) { + if (card.is_cursor(plane->plane_id)) { continue; } - if (card.is_cursor(plane->plane_id)) { - continue; + kms::plane_candidate_t candidate; + candidate.card_path = entry.path().generic_string(); + candidate.card_filename = filestring; + candidate.card_name = card.card_name; + candidate.crtc_id = plane->crtc_id; + candidate.crtc_index = card.get_crtc_index_by_id(plane->crtc_id); + candidate.plane_id = plane->plane_id; + candidate.possible_crtcs = plane->possible_crtcs; + + auto plane_props = card.plane_props(plane->plane_id); + auto plane_type_value = card.prop_value_by_name(plane_props, "type"sv); + candidate.plane_type = plane_type_value.value_or(0); + candidate.plane_type_name = std::string {kms::plane_type(candidate.plane_type)}; + + if (plane->crtc_id) { + if (auto crtc = card.crtc(plane->crtc_id)) { + candidate.crtc_width = crtc->width; + candidate.crtc_height = crtc->height; + } } - if (monitor != monitor_index) { - ++monitor; + auto connector = std::find_if(std::begin(connectors), std::end(connectors), [&](const auto &conn) { + return conn.crtc_id == plane->crtc_id; + }); + if (connector != std::end(connectors)) { + candidate.connector_name = kms::connector_name(connector->type, connector->index); + candidate.connector_id = connector->connector_id; + candidate.connector_connected = connector->connected; + } + + if (!plane->fb_id) { + candidate.skip_reason = "unused_no_fb"; + kms::log_plane_candidate("kms plane", candidate); continue; } + candidate.monitor_index = plane_monitor++; + auto fb = card.fb(plane.get()); if (!fb) { BOOST_LOG(error) << "Couldn't get drm fb for plane ["sv << plane->fb_id << "]: "sv << strerror(errno); - return -1; + candidate.skip_reason = "drm_fb_lookup_failed"; + kms::log_plane_candidate("kms plane", candidate); + continue; } + candidate.fb_id = fb->fb_id; + candidate.fb_width = fb->width; + candidate.fb_height = fb->height; + candidate.pixel_format = fb->pixel_format; + candidate.modifier = fb->modifier; + candidate.pitch0 = fb->pitches[0]; + candidate.sample = kms::sample_framebuffer(card, *fb); + if (!fb->handles[0]) { BOOST_LOG(error) << "Couldn't get handle for DRM Framebuffer ["sv << plane->fb_id << "]: Probably not permitted"sv; - return -1; + candidate.skip_reason = "missing_fb_handle"; + kms::log_plane_candidate("kms plane", candidate); + continue; } + bool missing_fd = false; for (int i = 0; i < 4; ++i) { if (!fb->handles[i]) { break; @@ -685,126 +983,181 @@ namespace platf { auto fb_fd = card.handleFD(fb->handles[i]); if (fb_fd.el < 0) { BOOST_LOG(error) << "Couldn't get primary file descriptor for Framebuffer ["sv << fb->fb_id << "]: "sv << strerror(errno); - continue; + missing_fd = true; + break; } } + if (missing_fd) { + candidate.skip_reason = "framebuffer_handlefd_failed"; + kms::log_plane_candidate("kms plane", candidate); + continue; + } auto crtc = card.crtc(plane->crtc_id); if (!crtc) { BOOST_LOG(error) << "Couldn't get CRTC info: "sv << strerror(errno); + candidate.skip_reason = "crtc_lookup_failed"; + kms::log_plane_candidate("kms plane", candidate); continue; } - BOOST_LOG(info) << "Found monitor for DRM screencasting"sv; + if (card_descriptor_pos != std::end(card_descriptors)) { + auto monitor = card_descriptor_pos->crtc_to_monitor.find(plane->crtc_id); + if (monitor != std::end(card_descriptor_pos->crtc_to_monitor)) { + candidate.monitor_index = monitor->second.monitor_index; + } + } - // We need to find the correct /dev/dri/card{nr} to correlate the crtc_id with the monitor descriptor - auto pos = std::find_if(std::begin(card_descriptors), std::end(card_descriptors), [&](card_descriptor_t &cd) { - return cd.path == filestring; - }); + if (forced_plane_id) { + if (candidate.plane_id != *forced_plane_id) { + candidate.skip_reason = "force_plane_mismatch"; + kms::log_plane_candidate("kms plane", candidate); + continue; + } + candidate.forced = true; + if (!forced_connector.empty() && candidate.connector_name != forced_connector) { + BOOST_LOG(warning) << "STREAM_DIAG forced plane connector mismatch" + << " plane_id="sv << candidate.plane_id + << " forced_connector="sv << forced_connector + << " candidate_connector="sv << candidate.connector_name; + } + } else if (!forced_connector.empty() && candidate.connector_name != forced_connector) { + candidate.skip_reason = "force_connector_mismatch"; + kms::log_plane_candidate("kms plane", candidate); + continue; + } + + candidate.skipped = false; + candidate.skip_reason = "candidate"; + candidate.score = kms::score_plane_candidate(candidate, config, monitor_index); + kms::log_plane_candidate("kms plane", candidate); - if (pos == std::end(card_descriptors)) { - // This code path shouldn't happen, but it's there just in case. - // card_descriptors is part of the guesswork after all. - BOOST_LOG(error) << "Couldn't find ["sv << entry.path() << "]: This shouldn't have happened :/"sv; - return -1; + if (!best_candidate || candidate.score > best_candidate->score) { + best_candidate = candidate; } + } + } - // TODO: surf_sd = fb->to_sd(); + if (!best_candidate) { + BOOST_LOG(error) << "Couldn't find monitor ["sv << monitor_index << ']'; + return -1; + } - kms::print(plane.get(), fb.get(), crtc.get()); + kms::log_plane_candidate("kms plane selected", *best_candidate); + if (best_candidate->forced) { + BOOST_LOG(warning) << "STREAM_DIAG KMS forced plane selected plane_id="sv << best_candidate->plane_id; + } - img_width = fb->width; - img_height = fb->height; - img_offset_x = crtc->x; - img_offset_y = crtc->y; + kms::card_t selected_card; + if (selected_card.init(best_candidate->card_path.c_str())) { + BOOST_LOG(error) << "Failed to reopen selected DRM card "sv << best_candidate->card_path; + return -1; + } - this->env_width = ::platf::kms::env_width; - this->env_height = ::platf::kms::env_height; + auto selected_plane = drmModeGetPlane(selected_card.fd.el, best_candidate->plane_id); + if (!selected_plane) { + BOOST_LOG(error) << "Couldn't reopen selected DRM plane ["sv << best_candidate->plane_id << "]: "sv << strerror(errno); + return -1; + } - this->env_logical_width = ::platf::kms::env_logical_width; - this->env_logical_height = ::platf::kms::env_logical_height; + auto selected_fb = selected_card.fb(selected_plane.get()); + if (!selected_fb) { + BOOST_LOG(error) << "Couldn't get drm fb for selected plane ["sv << selected_plane->fb_id << "]: "sv << strerror(errno); + return -1; + } - auto monitor = pos->crtc_to_monitor.find(plane->crtc_id); - if (monitor != std::end(pos->crtc_to_monitor)) { - auto &viewport = monitor->second.viewport; + auto selected_crtc = selected_card.crtc(selected_plane->crtc_id); + if (!selected_crtc) { + BOOST_LOG(error) << "Couldn't get selected CRTC info: "sv << strerror(errno); + return -1; + } - width = viewport.width; - height = viewport.height; + BOOST_LOG(info) << "Found monitor for DRM screencasting"sv; - logical_width = viewport.logical_width; - logical_height = viewport.logical_height; + auto pos = std::find_if(std::begin(card_descriptors), std::end(card_descriptors), [&](card_descriptor_t &cd) { + return cd.path == best_candidate->card_filename; + }); - switch (card.get_panel_orientation(plane->plane_id)) { - case DRM_MODE_ROTATE_270: - BOOST_LOG(debug) << "Detected panel orientation at 90, swapping width and height."; - width = viewport.height; - height = viewport.width; - break; - case DRM_MODE_ROTATE_90: - case DRM_MODE_ROTATE_180: - BOOST_LOG(warning) << "Panel orientation is unsupported, screen capture may not work correctly."; - break; - } + if (pos == std::end(card_descriptors)) { + BOOST_LOG(error) << "Couldn't find ["sv << best_candidate->card_filename << "]: This shouldn't have happened :/"sv; + return -1; + } - offset_x = viewport.offset_x; - offset_y = viewport.offset_y; - } + kms::print(selected_plane.get(), selected_fb.get(), selected_crtc.get()); - // This code path shouldn't happen, but it's there just in case. - // crtc_to_monitor is part of the guesswork after all. - else { - BOOST_LOG(warning) << "Couldn't find crtc_id, this shouldn't have happened :\\"sv; - width = crtc->width; - height = crtc->height; - offset_x = crtc->x; - offset_y = crtc->y; - } + img_width = selected_fb->width; + img_height = selected_fb->height; + img_offset_x = selected_crtc->x; + img_offset_y = selected_crtc->y; - plane_id = plane->plane_id; - crtc_id = plane->crtc_id; - crtc_index = card.get_crtc_index_by_id(plane->crtc_id); - card_path = entry.path().generic_string(); + this->env_width = ::platf::kms::env_width; + this->env_height = ::platf::kms::env_height; - auto plane_props = card.plane_props(plane->plane_id); - auto plane_type_value = card.prop_value_by_name(plane_props, "type"sv); - plane_type_name = std::string {kms::plane_type(plane_type_value.value_or(0))}; + this->env_logical_width = ::platf::kms::env_logical_width; + this->env_logical_height = ::platf::kms::env_logical_height; - // Find the connector for this CRTC - kms::conn_type_count_t conn_type_count; - for (auto &connector : card.monitors(conn_type_count)) { - if (connector.crtc_id == crtc_id) { - BOOST_LOG(info) << "Found connector ID ["sv << connector.connector_id << ']'; + auto monitor = pos->crtc_to_monitor.find(selected_plane->crtc_id); + if (monitor != std::end(pos->crtc_to_monitor)) { + auto &viewport = monitor->second.viewport; - connector_id = connector.connector_id; - connector_name = kms::connector_name(connector.type, connector.index); + width = viewport.width; + height = viewport.height; - auto connector_props = card.connector_props(*connector_id); - hdr_metadata_blob_id = card.prop_value_by_name(connector_props, "HDR_OUTPUT_METADATA"sv); - } - } + logical_width = viewport.logical_width; + logical_height = viewport.logical_height; - BOOST_LOG(info) << "STREAM_DIAG kms capture selected" - << " drm_device="sv << card_path - << " connector="sv << (connector_name.empty() ? "unknown" : connector_name) - << " connector_id="sv << (connector_id ? std::to_string(*connector_id) : std::string {""}) - << " crtc_id="sv << crtc_id - << " crtc_index="sv << crtc_index - << " plane_id="sv << plane_id - << " plane_type="sv << plane_type_name - << " framebuffer_id="sv << fb->fb_id - << " width="sv << fb->width - << " height="sv << fb->height - << " pixel_format="sv << util::view(fb->pixel_format) - << " modifier="sv << fb->modifier - << " pitch0="sv << fb->pitches[0]; - - this->card = std::move(card); - goto break_loop; + switch (selected_card.get_panel_orientation(selected_plane->plane_id)) { + case DRM_MODE_ROTATE_270: + BOOST_LOG(debug) << "Detected panel orientation at 90, swapping width and height."; + width = viewport.height; + height = viewport.width; + break; + case DRM_MODE_ROTATE_90: + case DRM_MODE_ROTATE_180: + BOOST_LOG(warning) << "Panel orientation is unsupported, screen capture may not work correctly."; + break; } + + offset_x = viewport.offset_x; + offset_y = viewport.offset_y; + } else { + BOOST_LOG(warning) << "Couldn't find crtc_id, this shouldn't have happened :\\"sv; + width = selected_crtc->width; + height = selected_crtc->height; + offset_x = selected_crtc->x; + offset_y = selected_crtc->y; } - BOOST_LOG(error) << "Couldn't find monitor ["sv << monitor_index << ']'; - return -1; + plane_id = selected_plane->plane_id; + crtc_id = selected_plane->crtc_id; + crtc_index = selected_card.get_crtc_index_by_id(selected_plane->crtc_id); + card_path = best_candidate->card_path; + plane_type_name = best_candidate->plane_type_name; + connector_id = best_candidate->connector_id; + connector_name = best_candidate->connector_name; + + if (connector_id) { + BOOST_LOG(info) << "Found connector ID ["sv << *connector_id << ']'; + auto connector_props = selected_card.connector_props(*connector_id); + hdr_metadata_blob_id = selected_card.prop_value_by_name(connector_props, "HDR_OUTPUT_METADATA"sv); + } + + BOOST_LOG(info) << "STREAM_DIAG kms capture selected" + << " drm_device="sv << card_path + << " connector="sv << (connector_name.empty() ? "unknown" : connector_name) + << " connector_id="sv << (connector_id ? std::to_string(*connector_id) : std::string {""}) + << " crtc_id="sv << crtc_id + << " crtc_index="sv << crtc_index + << " plane_id="sv << plane_id + << " plane_type="sv << plane_type_name + << " framebuffer_id="sv << selected_fb->fb_id + << " width="sv << selected_fb->width + << " height="sv << selected_fb->height + << " pixel_format="sv << util::view(selected_fb->pixel_format) + << " modifier="sv << selected_fb->modifier + << " pitch0="sv << selected_fb->pitches[0]; + + this->card = std::move(selected_card); // Neatly break from nested for loop break_loop: From e3226a286014d3ab10b9274cda2949094bd29f5c Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 12 May 2026 00:59:23 -0400 Subject: [PATCH 16/21] Fix KMS diagnostic build errors --- src/platform/linux/kmsgrab.cpp | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/src/platform/linux/kmsgrab.cpp b/src/platform/linux/kmsgrab.cpp index faaf3233a83..fedf4aa4716 100644 --- a/src/platform/linux/kmsgrab.cpp +++ b/src/platform/linux/kmsgrab.cpp @@ -1060,7 +1060,7 @@ namespace platf { return -1; } - auto selected_fb = selected_card.fb(selected_plane.get()); + auto selected_fb = selected_card.fb(selected_plane); if (!selected_fb) { BOOST_LOG(error) << "Couldn't get drm fb for selected plane ["sv << selected_plane->fb_id << "]: "sv << strerror(errno); return -1; @@ -1083,7 +1083,7 @@ namespace platf { return -1; } - kms::print(selected_plane.get(), selected_fb.get(), selected_crtc.get()); + kms::print(selected_plane, selected_fb.get(), selected_crtc.get()); img_width = selected_fb->width; img_height = selected_fb->height; @@ -1159,9 +1159,6 @@ namespace platf { this->card = std::move(selected_card); - // Neatly break from nested for loop - break_loop: - // Look for the cursor plane for this CRTC cursor_plane_id = -1; auto end = std::end(card); From 12fccf9ac74fc4579289b3f8e543b206bac1e9cd Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 12 May 2026 21:16:15 -0400 Subject: [PATCH 17/21] Add KMS DMA-BUF diagnostic capture fallbacks --- src/platform/linux/cuda.cpp | 7 +- src/platform/linux/graphics.cpp | 256 +++++++++++++++++++++++++++++--- src/platform/linux/graphics.h | 2 + 3 files changed, 241 insertions(+), 24 deletions(-) diff --git a/src/platform/linux/cuda.cpp b/src/platform/linux/cuda.cpp index 9fd5e529b42..4c48e8f91ae 100644 --- a/src/platform/linux/cuda.cpp +++ b/src/platform/linux/cuda.cpp @@ -381,7 +381,12 @@ namespace cuda { int convert(platf::img_t &img) override { auto &descriptor = (egl::img_descriptor_t &) img; - if (descriptor.sequence == 0) { + if (egl::diagnostic_gpu_solid_color_enabled()) { + if (descriptor.sequence > sequence || rgb->tex.size() == 0) { + sequence = descriptor.sequence; + rgb = egl::create_diagnostic_solid_color(img); + } + } else if (descriptor.sequence == 0) { // For dummy images, use a blank RGB texture instead of importing a DMA-BUF rgb = egl::create_blank(img); } else if (descriptor.sequence > sequence) { diff --git a/src/platform/linux/graphics.cpp b/src/platform/linux/graphics.cpp index 6cc2eb3bc3e..0c14d510c5f 100644 --- a/src/platform/linux/graphics.cpp +++ b/src/platform/linux/graphics.cpp @@ -3,7 +3,11 @@ * @brief Definitions for graphics related functions. */ // standard includes +#include +#include +#include #include +#include // local includes #include "graphics.h" @@ -551,13 +555,134 @@ namespace egl { return {}; } + bool stream_diag_env_enabled(const char *name) { + const auto *value = std::getenv(name); + if (!value) { + return false; + } + + const std::string_view flag {value}; + return flag != "0"sv && flag != "false"sv && flag != "FALSE"sv && flag != "no"sv && flag != "NO"sv; + } + + const char *stream_diag_env_or_unset(const char *name) { + const auto *value = std::getenv(name); + return value ? value : ""; + } + + std::string stream_diag_fourcc_to_string(std::uint32_t fourcc) { + std::string text; + text.resize(4); + for (int i = 0; i < 4; ++i) { + const auto ch = static_cast((fourcc >> (i * 8)) & 0xFF); + text[i] = (ch >= 32 && ch <= 126) ? ch : '.'; + } + return text; + } + + bool stream_diag_should_log(std::atomic_uint64_t &counter) { + const auto count = counter.fetch_add(1) + 1; + return count <= 60 || count % 120 == 0; + } + + bool stream_diag_drain_gl_errors(const std::string_view &prefix, GLenum *first_error = nullptr) { + bool had_error = false; + GLenum err; + while ((err = gl::ctx.GetError()) != GL_NO_ERROR) { + if (!had_error && first_error) { + *first_error = err; + } + had_error = true; + BOOST_LOG(error) << "GL: "sv << prefix << ": ["sv << util::hex(err).to_string_view() << ']'; + } + return had_error; + } + + std::optional> stream_diag_color_from_env(const char *name) { + const auto *value = std::getenv(name); + if (!value) { + return std::nullopt; + } + + const std::string_view color {value}; + if (color == "red"sv) { + return std::array {1.0f, 0.0f, 0.0f, 1.0f}; + } + if (color == "magenta"sv) { + return std::array {1.0f, 0.0f, 1.0f, 1.0f}; + } + + BOOST_LOG(warning) << "STREAM_DIAG unsupported diagnostic color "sv << name << '=' << color + << " supported=red,magenta"sv; + return std::nullopt; + } + + rgb_t create_solid_color_texture(platf::img_t &img, const std::array &color) { + rgb_t rgb { + EGL_NO_DISPLAY, + EGL_NO_IMAGE, + gl::tex_t::make(1) + }; + + gl::ctx.BindTexture(GL_TEXTURE_2D, rgb->tex[0]); + gl::ctx.TexStorage2D(GL_TEXTURE_2D, 1, GL_RGBA8, img.width, img.height); + gl::ctx.BindTexture(GL_TEXTURE_2D, 0); + + auto framebuf = gl::frame_buf_t::make(1); + framebuf.bind(&rgb->tex[0], &rgb->tex[0] + 1); + + gl::ctx.BindFramebuffer(GL_FRAMEBUFFER, framebuf[0]); + const auto status = gl::ctx.CheckFramebufferStatus(GL_FRAMEBUFFER); + if (status != GL_FRAMEBUFFER_COMPLETE) { + BOOST_LOG(error) << "STREAM_DIAG diagnostic solid texture framebuffer incomplete status=0x"sv + << util::hex(status).to_string_view() + << " texture="sv << rgb->tex[0] + << " width="sv << img.width + << " height="sv << img.height; + } + + GLenum attachment = GL_COLOR_ATTACHMENT0; + gl::ctx.DrawBuffers(1, &attachment); + gl::ctx.ClearBufferfv(GL_COLOR, 0, color.data()); + gl::ctx.BindFramebuffer(GL_FRAMEBUFFER, 0); + + stream_diag_drain_gl_errors("STREAM_DIAG create_solid_color_texture"sv); + + return rgb; + } + /** * @brief Get EGL attributes for eglCreateImage() to import the provided surface. * @param surface The surface descriptor. * @return Vector of EGL attributes. */ std::vector surface_descriptor_to_egl_attribs(const surface_descriptor_t &surface) { + static std::atomic_uint64_t attr_log_counter {0}; + std::vector attribs; + const bool omit_linear_modifier = stream_diag_env_enabled("SUNSHINE_STREAM_DIAG_OMIT_LINEAR_MODIFIER"); + const bool include_modifier = surface.modifier != DRM_FORMAT_MOD_INVALID && !(omit_linear_modifier && surface.modifier == 0); + const bool log_this = stream_diag_should_log(attr_log_counter); + + int fd_count = 0; + for (auto fd : surface.fds) { + if (fd >= 0) { + ++fd_count; + } + } + + if (log_this) { + BOOST_LOG(info) << "STREAM_DIAG egl dmabuf attribs" + << " width="sv << surface.width + << " height="sv << surface.height + << " fourcc="sv << stream_diag_fourcc_to_string(surface.fourcc) + << " fourcc_hex=0x"sv << util::hex(surface.fourcc).to_string_view() + << " fd_count="sv << fd_count + << " modifier="sv << surface.modifier + << " modifier_hex=0x"sv << util::hex(surface.modifier).to_string_view() + << " include_modifiers="sv << include_modifier + << " omit_linear_modifier_env="sv << omit_linear_modifier; + } attribs.emplace_back(EGL_WIDTH); attribs.emplace_back(surface.width); @@ -581,7 +706,16 @@ namespace egl { attribs.emplace_back(plane_attr.pitch); attribs.emplace_back(surface.pitches[x]); - if (surface.modifier != DRM_FORMAT_MOD_INVALID) { + if (log_this) { + BOOST_LOG(info) << "STREAM_DIAG egl dmabuf plane" + << " index="sv << x + << " fd="sv << fd + << " offset="sv << surface.offsets[x] + << " pitch="sv << surface.pitches[x] + << " modifier_included="sv << include_modifier; + } + + if (include_modifier) { attribs.emplace_back(plane_attr.lo); attribs.emplace_back(surface.modifier & 0xFFFFFFFF); attribs.emplace_back(plane_attr.hi); @@ -595,6 +729,8 @@ namespace egl { std::optional import_source(display_t::pointer egl_display, const surface_descriptor_t &xrgb) { auto attribs = surface_descriptor_to_egl_attribs(xrgb); + static std::atomic_uint64_t import_log_counter {0}; + const bool log_this = stream_diag_should_log(import_log_counter); rgb_t rgb { egl_display, @@ -613,8 +749,39 @@ namespace egl { BOOST_LOG(error) << "glEGLImageTargetTexture2DOES is not available; cannot import RGB DMA-BUF"sv; return std::nullopt; } + + stream_diag_drain_gl_errors("STREAM_DIAG import_source before glEGLImageTargetTexture2DOES"sv); gl::egl_image_target_texture_2d()(GL_TEXTURE_2D, rgb->xrgb8); + GLenum first_error = GL_NO_ERROR; + const bool import_gl_error = stream_diag_drain_gl_errors("STREAM_DIAG import_source after glEGLImageTargetTexture2DOES"sv, &first_error); + if (import_gl_error) { + if (first_error == GL_INVALID_OPERATION) { + BOOST_LOG(error) << "STREAM_DIAG import_source glEGLImageTargetTexture2DOES failed" + << " target=GL_TEXTURE_2D" + << " fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) + << " fourcc_hex=0x"sv << util::hex(xrgb.fourcc).to_string_view() + << " modifier="sv << xrgb.modifier + << " modifier_hex=0x"sv << util::hex(xrgb.modifier).to_string_view() + << " pitch0="sv << xrgb.pitches[0] + << " width="sv << xrgb.width + << " height="sv << xrgb.height; + } + + gl::ctx.BindTexture(GL_TEXTURE_2D, 0); + return std::nullopt; + } + + if (log_this) { + BOOST_LOG(info) << "STREAM_DIAG import_source succeeded" + << " texture="sv << rgb->tex[0] + << " width="sv << xrgb.width + << " height="sv << xrgb.height + << " fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) + << " modifier="sv << xrgb.modifier + << " pitch0="sv << xrgb.pitches[0]; + } + gl::ctx.BindTexture(GL_TEXTURE_2D, 0); gl_drain_errors; @@ -622,33 +789,44 @@ namespace egl { return rgb; } + bool diagnostic_gpu_solid_color_enabled() { + return stream_diag_color_from_env("SUNSHINE_STREAM_DIAG_GPU_SOLID_COLOR").has_value(); + } + + rgb_t create_diagnostic_solid_color(platf::img_t &img) { + static std::atomic_bool logged_enabled {false}; + const auto color = stream_diag_color_from_env("SUNSHINE_STREAM_DIAG_GPU_SOLID_COLOR") + .value_or(std::array {1.0f, 0.0f, 1.0f, 1.0f}); + + if (!logged_enabled.exchange(true)) { + BOOST_LOG(warning) << "STREAM_DIAG GPU solid color source active" + << " color="sv << stream_diag_env_or_unset("SUNSHINE_STREAM_DIAG_GPU_SOLID_COLOR") + << " width="sv << img.width + << " height="sv << img.height; + } + + return create_solid_color_texture(img, color); + } + /** * @brief Create a black RGB texture of the specified image size. * @param img The image to use for texture sizing. * @return The new RGB texture. */ rgb_t create_blank(platf::img_t &img) { - rgb_t rgb { - EGL_NO_DISPLAY, - EGL_NO_IMAGE, - gl::tex_t::make(1) - }; - - gl::ctx.BindTexture(GL_TEXTURE_2D, rgb->tex[0]); - gl::ctx.TexStorage2D(GL_TEXTURE_2D, 1, GL_RGBA8, img.width, img.height); - gl::ctx.BindTexture(GL_TEXTURE_2D, 0); - - auto framebuf = gl::frame_buf_t::make(1); - framebuf.bind(&rgb->tex[0], &rgb->tex[0] + 1); - - GLenum attachment = GL_COLOR_ATTACHMENT0; - gl::ctx.DrawBuffers(1, &attachment); - const GLuint rgb_black[] = {0, 0, 0, 0}; - gl::ctx.ClearBufferuiv(GL_COLOR, 0, rgb_black); - - gl_drain_errors; + const auto color = stream_diag_color_from_env("SUNSHINE_STREAM_DIAG_BLANK_COLOR"); + if (color) { + static std::atomic_bool logged_blank_color {false}; + if (!logged_blank_color.exchange(true)) { + BOOST_LOG(warning) << "STREAM_DIAG create_blank diagnostic color active" + << " color="sv << stream_diag_env_or_unset("SUNSHINE_STREAM_DIAG_BLANK_COLOR") + << " width="sv << img.width + << " height="sv << img.height; + } + return create_solid_color_texture(img, *color); + } - return rgb; + return create_solid_color_texture(img, {0.0f, 0.0f, 0.0f, 1.0f}); } std::optional import_target(display_t::pointer egl_display, std::array &&fds, const surface_descriptor_t &y, const surface_descriptor_t &uv) { @@ -1024,8 +1202,24 @@ namespace egl { } int sws_t::convert(gl::frame_buf_t &fb) { + static std::atomic_uint64_t convert_log_counter {0}; + const bool log_this = stream_diag_should_log(convert_log_counter); + gl::ctx.BindTexture(GL_TEXTURE_2D, loaded_texture); + if (log_this) { + BOOST_LOG(info) << "STREAM_DIAG rgb_to_yuv begin" + << " source_texture="sv << loaded_texture + << " framebuffer0="sv << fb[0] + << " framebuffer1="sv << fb[1] + << " in_width="sv << in_width + << " in_height="sv << in_height + << " out_width="sv << out_width + << " out_height="sv << out_height + << " offsetX="sv << offsetX + << " offsetY="sv << offsetY; + } + GLenum attachments[] { GL_COLOR_ATTACHMENT0, GL_COLOR_ATTACHMENT1 @@ -1035,17 +1229,33 @@ namespace egl { gl::ctx.BindFramebuffer(GL_FRAMEBUFFER, fb[x]); gl::ctx.DrawBuffers(1, &attachments[x]); -#ifndef NDEBUG auto status = gl::ctx.CheckFramebufferStatus(GL_FRAMEBUFFER); + if (log_this) { + GLint target_texture = 0; + gl::ctx.GetFramebufferAttachmentParameteriv(GL_FRAMEBUFFER, attachments[x], GL_FRAMEBUFFER_ATTACHMENT_OBJECT_NAME, &target_texture); + BOOST_LOG(info) << "STREAM_DIAG rgb_to_yuv framebuffer" + << " plane="sv << x + << " framebuffer="sv << fb[x] + << " target_texture="sv << target_texture + << " completeness=0x"sv << util::hex(status).to_string_view(); + } + if (status != GL_FRAMEBUFFER_COMPLETE) { BOOST_LOG(error) << "Pass "sv << x << ": CheckFramebufferStatus() --> [0x"sv << util::hex(status).to_string_view() << ']'; +#ifndef NDEBUG return -1; - } #endif + } + if (log_this) { + stream_diag_drain_gl_errors("STREAM_DIAG rgb_to_yuv before draw"sv); + } gl::ctx.UseProgram(program[x].handle()); gl::ctx.Viewport(offsetX / (x + 1), offsetY / (x + 1), out_width / (x + 1), out_height / (x + 1)); gl::ctx.DrawArrays(GL_TRIANGLES, 0, 3); + if (log_this) { + stream_diag_drain_gl_errors("STREAM_DIAG rgb_to_yuv after draw"sv); + } } gl::ctx.BindTexture(GL_TEXTURE_2D, 0); diff --git a/src/platform/linux/graphics.h b/src/platform/linux/graphics.h index 286a700bf25..1e629f099d4 100644 --- a/src/platform/linux/graphics.h +++ b/src/platform/linux/graphics.h @@ -254,6 +254,8 @@ namespace egl { ); rgb_t create_blank(platf::img_t &img); + bool diagnostic_gpu_solid_color_enabled(); + rgb_t create_diagnostic_solid_color(platf::img_t &img); std::optional import_target( display_t::pointer egl_display, From 3fefabcc552dca701de89bee3af6924f0c1749fa Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 12 May 2026 21:46:43 -0400 Subject: [PATCH 18/21] Add KMS DMA-BUF import target experiments --- src/platform/linux/graphics.cpp | 478 +++++++++++++++++++++++++++++--- 1 file changed, 433 insertions(+), 45 deletions(-) diff --git a/src/platform/linux/graphics.cpp b/src/platform/linux/graphics.cpp index 0c14d510c5f..59e5f215a1c 100644 --- a/src/platform/linux/graphics.cpp +++ b/src/platform/linux/graphics.cpp @@ -31,6 +31,21 @@ extern "C" { #define fourcc_code(a, b, c, d) ((std::uint32_t) (a) | ((std::uint32_t) (b) << 8) | ((std::uint32_t) (c) << 16) | ((std::uint32_t) (d) << 24)) #define fourcc_mod_code(vendor, val) ((((uint64_t) vendor) << 56) | ((val) & 0x00ffffffffffffffULL)) #define DRM_FORMAT_MOD_INVALID fourcc_mod_code(0, ((1ULL << 56) - 1)) +#ifndef DRM_FORMAT_XRGB8888 + #define DRM_FORMAT_XRGB8888 fourcc_code('X', 'R', '2', '4') +#endif + +#ifndef DRM_FORMAT_ARGB8888 + #define DRM_FORMAT_ARGB8888 fourcc_code('A', 'R', '2', '4') +#endif + +#ifndef GL_TEXTURE_EXTERNAL_OES + #define GL_TEXTURE_EXTERNAL_OES 0x8D65 +#endif + +#ifndef GL_TEXTURE_RECTANGLE + #define GL_TEXTURE_RECTANGLE 0x84F5 +#endif #if !defined(SUNSHINE_SHADERS_DIR) // for testing this needs to be defined in cmake as we don't do an install #define SUNSHINE_SHADERS_DIR SUNSHINE_ASSETS_DIR "/shaders/opengl" @@ -565,6 +580,11 @@ namespace egl { return flag != "0"sv && flag != "false"sv && flag != "FALSE"sv && flag != "no"sv && flag != "NO"sv; } + std::string_view stream_diag_env_value(const char *name) { + const auto *value = std::getenv(name); + return value ? std::string_view {value} : std::string_view {}; + } + const char *stream_diag_env_or_unset(const char *name) { const auto *value = std::getenv(name); return value ? value : ""; @@ -585,6 +605,19 @@ namespace egl { return count <= 60 || count % 120 == 0; } + std::string_view stream_diag_texture_target_to_string(GLenum target) { + switch (target) { + case GL_TEXTURE_2D: + return "GL_TEXTURE_2D"sv; + case GL_TEXTURE_EXTERNAL_OES: + return "GL_TEXTURE_EXTERNAL_OES"sv; + case GL_TEXTURE_RECTANGLE: + return "GL_TEXTURE_RECTANGLE"sv; + default: + return "UNKNOWN"sv; + } + } + bool stream_diag_drain_gl_errors(const std::string_view &prefix, GLenum *first_error = nullptr) { bool had_error = false; GLenum err; @@ -656,12 +689,10 @@ namespace egl { * @param surface The surface descriptor. * @return Vector of EGL attributes. */ - std::vector surface_descriptor_to_egl_attribs(const surface_descriptor_t &surface) { + std::vector surface_descriptor_to_egl_attribs(const surface_descriptor_t &surface, std::uint32_t import_fourcc, bool include_modifier, const std::string_view &attempt_label) { static std::atomic_uint64_t attr_log_counter {0}; std::vector attribs; - const bool omit_linear_modifier = stream_diag_env_enabled("SUNSHINE_STREAM_DIAG_OMIT_LINEAR_MODIFIER"); - const bool include_modifier = surface.modifier != DRM_FORMAT_MOD_INVALID && !(omit_linear_modifier && surface.modifier == 0); const bool log_this = stream_diag_should_log(attr_log_counter); int fd_count = 0; @@ -673,15 +704,17 @@ namespace egl { if (log_this) { BOOST_LOG(info) << "STREAM_DIAG egl dmabuf attribs" + << " attempt="sv << attempt_label << " width="sv << surface.width << " height="sv << surface.height - << " fourcc="sv << stream_diag_fourcc_to_string(surface.fourcc) - << " fourcc_hex=0x"sv << util::hex(surface.fourcc).to_string_view() + << " original_fourcc="sv << stream_diag_fourcc_to_string(surface.fourcc) + << " original_fourcc_hex=0x"sv << util::hex(surface.fourcc).to_string_view() + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " import_fourcc_hex=0x"sv << util::hex(import_fourcc).to_string_view() << " fd_count="sv << fd_count << " modifier="sv << surface.modifier << " modifier_hex=0x"sv << util::hex(surface.modifier).to_string_view() - << " include_modifiers="sv << include_modifier - << " omit_linear_modifier_env="sv << omit_linear_modifier; + << " include_modifiers="sv << include_modifier; } attribs.emplace_back(EGL_WIDTH); @@ -689,7 +722,7 @@ namespace egl { attribs.emplace_back(EGL_HEIGHT); attribs.emplace_back(surface.height); attribs.emplace_back(EGL_LINUX_DRM_FOURCC_EXT); - attribs.emplace_back(surface.fourcc); + attribs.emplace_back(import_fourcc); for (auto x = 0; x < 4; ++x) { auto fd = surface.fds[x]; @@ -727,65 +760,420 @@ namespace egl { return attribs; } - std::optional import_source(display_t::pointer egl_display, const surface_descriptor_t &xrgb) { - auto attribs = surface_descriptor_to_egl_attribs(xrgb); - static std::atomic_uint64_t import_log_counter {0}; - const bool log_this = stream_diag_should_log(import_log_counter); + bool surface_default_include_modifier(const surface_descriptor_t &surface) { + const bool omit_linear_modifier = stream_diag_env_enabled("SUNSHINE_STREAM_DIAG_OMIT_LINEAR_MODIFIER"); + return surface.modifier != DRM_FORMAT_MOD_INVALID && !(omit_linear_modifier && surface.modifier == 0); + } - rgb_t rgb { - egl_display, - eglCreateImage(egl_display, EGL_NO_CONTEXT, EGL_LINUX_DMA_BUF_EXT, nullptr, attribs.data()), - gl::tex_t::make(1) + GLenum stream_diag_import_target_from_env() { + const auto target = stream_diag_env_value("SUNSHINE_STREAM_DIAG_IMPORT_TARGET"); + if (target.empty() || target == "2d"sv || target == "2D"sv) { + return GL_TEXTURE_2D; + } + if (target == "external"sv || target == "EXTERNAL"sv) { + return GL_TEXTURE_EXTERNAL_OES; + } + if (target == "rectangle"sv || target == "RECTANGLE"sv) { + return GL_TEXTURE_RECTANGLE; + } + + BOOST_LOG(warning) << "STREAM_DIAG unsupported SUNSHINE_STREAM_DIAG_IMPORT_TARGET="sv << target + << " supported=2d,external,rectangle; using GL_TEXTURE_2D"sv; + return GL_TEXTURE_2D; + } + + std::uint32_t stream_diag_import_fourcc_from_env(std::uint32_t original_fourcc) { + const auto override = stream_diag_env_value("SUNSHINE_STREAM_DIAG_IMPORT_FOURCC_OVERRIDE"); + if (override.empty()) { + return original_fourcc; + } + + if (override == "AR24"sv && original_fourcc == DRM_FORMAT_XRGB8888) { + BOOST_LOG(warning) << "STREAM_DIAG import fourcc override active" + << " original_fourcc="sv << stream_diag_fourcc_to_string(original_fourcc) + << " import_fourcc=AR24"sv; + return DRM_FORMAT_ARGB8888; + } + + BOOST_LOG(warning) << "STREAM_DIAG import fourcc override skipped" + << " requested="sv << override + << " original_fourcc="sv << stream_diag_fourcc_to_string(original_fourcc) + << " supported_override=AR24_for_XR24"sv; + return original_fourcc; + } + + std::optional make_import_blit_program(GLenum source_target) { + constexpr std::string_view vertex_shader_300_es { + R"(#version 300 es +#ifdef GL_ES +precision mediump float; +#endif +out vec2 tex; +void main() +{ + float idHigh = float(gl_VertexID >> 1); + float idLow = float(gl_VertexID & int(1)); + float x = idHigh * 4.0 - 1.0; + float y = idLow * 4.0 - 1.0; + float u = idHigh * 2.0; + float v = idLow * 2.0; + gl_Position = vec4(x, y, 0.0, 1.0); + tex = vec2(u, v); +} +)" }; - if (!rgb->xrgb8) { - BOOST_LOG(error) << "Couldn't import RGB Image: "sv << util::hex(eglGetError()).to_string_view(); + constexpr std::string_view vertex_shader_330 { + R"(#version 330 core +out vec2 tex; +void main() +{ + float idHigh = float(gl_VertexID >> 1); + float idLow = float(gl_VertexID & int(1)); + float x = idHigh * 4.0 - 1.0; + float y = idLow * 4.0 - 1.0; + float u = idHigh * 2.0; + float v = idLow * 2.0; + gl_Position = vec4(x, y, 0.0, 1.0); + tex = vec2(u, v); +} +)" + }; + + constexpr std::string_view external_fragment_shader { + R"(#version 300 es +#extension GL_OES_EGL_image_external_essl3 : require +#ifdef GL_ES +precision mediump float; +#endif +uniform samplerExternalOES image; +in vec2 tex; +layout(location = 0) out vec4 color; +void main() +{ + color = texture(image, tex); +} +)" + }; + + constexpr std::string_view rectangle_fragment_shader { + R"(#version 330 core +uniform sampler2DRect image; +uniform vec2 source_size; +in vec2 tex; +out vec4 color; +void main() +{ + color = texture(image, tex * source_size); +} +)" + }; + const auto vertex_source = source_target == GL_TEXTURE_RECTANGLE ? vertex_shader_330 : vertex_shader_300_es; + const auto fragment_source = source_target == GL_TEXTURE_RECTANGLE ? rectangle_fragment_shader : external_fragment_shader; + + auto vertex = gl::shader_t::compile(vertex_source, GL_VERTEX_SHADER); + stream_diag_drain_gl_errors("STREAM_DIAG import blit vertex shader compile"sv); + if (vertex.has_right()) { + BOOST_LOG(error) << "STREAM_DIAG import blit vertex shader failed target="sv + << stream_diag_texture_target_to_string(source_target) + << " error="sv << vertex.right(); return std::nullopt; } - gl::ctx.BindTexture(GL_TEXTURE_2D, rgb->tex[0]); + auto fragment = gl::shader_t::compile(fragment_source, GL_FRAGMENT_SHADER); + stream_diag_drain_gl_errors("STREAM_DIAG import blit fragment shader compile"sv); + if (fragment.has_right()) { + BOOST_LOG(error) << "STREAM_DIAG import blit fragment shader failed target="sv + << stream_diag_texture_target_to_string(source_target) + << " error="sv << fragment.right(); + return std::nullopt; + } + + auto program = gl::program_t::link(vertex.left(), fragment.left()); + stream_diag_drain_gl_errors("STREAM_DIAG import blit program link"sv); + if (program.has_right()) { + BOOST_LOG(error) << "STREAM_DIAG import blit program link failed target="sv + << stream_diag_texture_target_to_string(source_target) + << " error="sv << program.right(); + return std::nullopt; + } + + return std::move(program.left()); + } + + bool blit_imported_texture_to_2d(GLenum source_target, GLuint source_texture, GLuint output_texture, int width, int height, const std::string_view &attempt_label) { + auto program = make_import_blit_program(source_target); + if (!program) { + return false; + } + + auto framebuf = gl::frame_buf_t::make(1); + framebuf.bind(&output_texture, &output_texture + 1); + + gl::ctx.BindFramebuffer(GL_FRAMEBUFFER, framebuf[0]); + GLenum attachment = GL_COLOR_ATTACHMENT0; + gl::ctx.DrawBuffers(1, &attachment); + + const auto status = gl::ctx.CheckFramebufferStatus(GL_FRAMEBUFFER); + BOOST_LOG(info) << "STREAM_DIAG import blit framebuffer" + << " attempt="sv << attempt_label + << " source_target="sv << stream_diag_texture_target_to_string(source_target) + << " source_texture="sv << source_texture + << " output_texture="sv << output_texture + << " framebuffer="sv << framebuf[0] + << " completeness=0x"sv << util::hex(status).to_string_view(); + + if (status != GL_FRAMEBUFFER_COMPLETE) { + gl::ctx.BindFramebuffer(GL_FRAMEBUFFER, 0); + return false; + } + + stream_diag_drain_gl_errors("STREAM_DIAG import blit before draw"sv); + gl::ctx.ActiveTexture(GL_TEXTURE0); + gl::ctx.BindTexture(source_target, source_texture); + gl::ctx.UseProgram(program->handle()); + + const auto image_uniform = gl::ctx.GetUniformLocation(program->handle(), "image"); + if (image_uniform >= 0) { + gl::ctx.Uniform1i(image_uniform, 0); + } + + if (source_target == GL_TEXTURE_RECTANGLE) { + const auto source_size_uniform = gl::ctx.GetUniformLocation(program->handle(), "source_size"); + if (source_size_uniform >= 0) { + gl::ctx.Uniform2f(source_size_uniform, static_cast(width), static_cast(height)); + } + } + + gl::ctx.Viewport(0, 0, width, height); + gl::ctx.DrawArrays(GL_TRIANGLES, 0, 3); + + GLenum first_error = GL_NO_ERROR; + const bool had_error = stream_diag_drain_gl_errors("STREAM_DIAG import blit after draw"sv, &first_error); + gl::ctx.BindTexture(source_target, 0); + gl::ctx.BindFramebuffer(GL_FRAMEBUFFER, 0); + + if (had_error) { + BOOST_LOG(error) << "STREAM_DIAG import blit failed" + << " attempt="sv << attempt_label + << " source_target="sv << stream_diag_texture_target_to_string(source_target) + << " gl_error=0x"sv << util::hex(first_error).to_string_view(); + return false; + } + + BOOST_LOG(info) << "STREAM_DIAG import blit succeeded" + << " attempt="sv << attempt_label + << " source_target="sv << stream_diag_texture_target_to_string(source_target) + << " source_texture="sv << source_texture + << " output_texture="sv << output_texture; + return true; + } + + bool configure_import_texture(GLenum target) { + gl::ctx.TexParameteri(target, GL_TEXTURE_WRAP_S, GL_CLAMP_TO_EDGE); + gl::ctx.TexParameteri(target, GL_TEXTURE_WRAP_T, GL_CLAMP_TO_EDGE); + gl::ctx.TexParameteri(target, GL_TEXTURE_MIN_FILTER, GL_LINEAR); + gl::ctx.TexParameteri(target, GL_TEXTURE_MAG_FILTER, GL_LINEAR); + return !stream_diag_drain_gl_errors("STREAM_DIAG configure import texture"sv); + } + + std::optional try_import_source_attempt(display_t::pointer egl_display, const surface_descriptor_t &source, std::uint32_t import_fourcc, bool include_modifier, GLenum texture_target, const std::string_view &attempt_label) { + auto attribs = surface_descriptor_to_egl_attribs(source, import_fourcc, include_modifier, attempt_label); + EGLImage image = eglCreateImage(egl_display, EGL_NO_CONTEXT, EGL_LINUX_DMA_BUF_EXT, nullptr, attribs.data()); + if (!image) { + const auto egl_error = eglGetError(); + BOOST_LOG(error) << "STREAM_DIAG import attempt eglCreateImage failed" + << " attempt="sv << attempt_label + << " original_fourcc="sv << stream_diag_fourcc_to_string(source.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " target="sv << stream_diag_texture_target_to_string(texture_target) + << " include_modifiers="sv << include_modifier + << " modifier="sv << source.modifier + << " pitch0="sv << source.pitches[0] + << " egl_error=0x"sv << util::hex(egl_error).to_string_view(); + return std::nullopt; + } + + BOOST_LOG(info) << "STREAM_DIAG import attempt eglCreateImage succeeded" + << " attempt="sv << attempt_label + << " original_fourcc="sv << stream_diag_fourcc_to_string(source.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " target="sv << stream_diag_texture_target_to_string(texture_target) + << " include_modifiers="sv << include_modifier + << " modifier="sv << source.modifier + << " pitch0="sv << source.pitches[0] + << " width="sv << source.width + << " height="sv << source.height; + if (!gl::egl_image_target_texture_2d()) { BOOST_LOG(error) << "glEGLImageTargetTexture2DOES is not available; cannot import RGB DMA-BUF"sv; + eglDestroyImage(egl_display, image); return std::nullopt; } - stream_diag_drain_gl_errors("STREAM_DIAG import_source before glEGLImageTargetTexture2DOES"sv); - gl::egl_image_target_texture_2d()(GL_TEXTURE_2D, rgb->xrgb8); + if (texture_target == GL_TEXTURE_2D) { + rgb_t rgb { + egl_display, + image, + gl::tex_t::make(1) + }; - GLenum first_error = GL_NO_ERROR; - const bool import_gl_error = stream_diag_drain_gl_errors("STREAM_DIAG import_source after glEGLImageTargetTexture2DOES"sv, &first_error); - if (import_gl_error) { - if (first_error == GL_INVALID_OPERATION) { + gl::ctx.BindTexture(GL_TEXTURE_2D, rgb->tex[0]); + stream_diag_drain_gl_errors("STREAM_DIAG import_source before glEGLImageTargetTexture2DOES"sv); + gl::egl_image_target_texture_2d()(GL_TEXTURE_2D, rgb->xrgb8); + + GLenum first_error = GL_NO_ERROR; + const bool import_gl_error = stream_diag_drain_gl_errors("STREAM_DIAG import_source after glEGLImageTargetTexture2DOES"sv, &first_error); + if (import_gl_error) { BOOST_LOG(error) << "STREAM_DIAG import_source glEGLImageTargetTexture2DOES failed" - << " target=GL_TEXTURE_2D" - << " fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) - << " fourcc_hex=0x"sv << util::hex(xrgb.fourcc).to_string_view() - << " modifier="sv << xrgb.modifier - << " modifier_hex=0x"sv << util::hex(xrgb.modifier).to_string_view() - << " pitch0="sv << xrgb.pitches[0] - << " width="sv << xrgb.width - << " height="sv << xrgb.height; + << " attempt="sv << attempt_label + << " target="sv << stream_diag_texture_target_to_string(texture_target) + << " original_fourcc="sv << stream_diag_fourcc_to_string(source.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " modifier="sv << source.modifier + << " modifier_hex=0x"sv << util::hex(source.modifier).to_string_view() + << " include_modifiers="sv << include_modifier + << " pitch0="sv << source.pitches[0] + << " width="sv << source.width + << " height="sv << source.height + << " gl_error=0x"sv << util::hex(first_error).to_string_view(); + gl::ctx.BindTexture(GL_TEXTURE_2D, 0); + return std::nullopt; } + BOOST_LOG(info) << "STREAM_DIAG import attempt glEGLImageTargetTexture2DOES succeeded" + << " attempt="sv << attempt_label + << " target="sv << stream_diag_texture_target_to_string(texture_target) + << " texture="sv << rgb->tex[0] + << " original_fourcc="sv << stream_diag_fourcc_to_string(source.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc); + gl::ctx.BindTexture(GL_TEXTURE_2D, 0); - return std::nullopt; + return std::move(rgb); } - if (log_this) { - BOOST_LOG(info) << "STREAM_DIAG import_source succeeded" - << " texture="sv << rgb->tex[0] - << " width="sv << xrgb.width - << " height="sv << xrgb.height - << " fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) - << " modifier="sv << xrgb.modifier - << " pitch0="sv << xrgb.pitches[0]; + GLuint import_texture = 0; + gl::ctx.GenTextures(1, &import_texture); + gl::ctx.BindTexture(texture_target, import_texture); + configure_import_texture(texture_target); + + stream_diag_drain_gl_errors("STREAM_DIAG import_source alt target before glEGLImageTargetTexture2DOES"sv); + gl::egl_image_target_texture_2d()(texture_target, image); + + GLenum first_error = GL_NO_ERROR; + const bool import_gl_error = stream_diag_drain_gl_errors("STREAM_DIAG import_source alt target after glEGLImageTargetTexture2DOES"sv, &first_error); + if (import_gl_error) { + BOOST_LOG(error) << "STREAM_DIAG import_source glEGLImageTargetTexture2DOES failed" + << " attempt="sv << attempt_label + << " target="sv << stream_diag_texture_target_to_string(texture_target) + << " original_fourcc="sv << stream_diag_fourcc_to_string(source.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " modifier="sv << source.modifier + << " include_modifiers="sv << include_modifier + << " pitch0="sv << source.pitches[0] + << " width="sv << source.width + << " height="sv << source.height + << " gl_error=0x"sv << util::hex(first_error).to_string_view(); + gl::ctx.BindTexture(texture_target, 0); + gl::ctx.DeleteTextures(1, &import_texture); + eglDestroyImage(egl_display, image); + return std::nullopt; } + BOOST_LOG(info) << "STREAM_DIAG import attempt glEGLImageTargetTexture2DOES succeeded" + << " attempt="sv << attempt_label + << " target="sv << stream_diag_texture_target_to_string(texture_target) + << " texture="sv << import_texture + << " original_fourcc="sv << stream_diag_fourcc_to_string(source.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc); + + rgb_t rgb { + EGL_NO_DISPLAY, + EGL_NO_IMAGE, + gl::tex_t::make(1) + }; + + gl::ctx.BindTexture(GL_TEXTURE_2D, rgb->tex[0]); + gl::ctx.TexStorage2D(GL_TEXTURE_2D, 1, GL_RGBA8, source.width, source.height); gl::ctx.BindTexture(GL_TEXTURE_2D, 0); - gl_drain_errors; + const bool blit_ok = blit_imported_texture_to_2d(texture_target, import_texture, rgb->tex[0], source.width, source.height, attempt_label); + gl::ctx.BindTexture(texture_target, 0); + gl::ctx.DeleteTextures(1, &import_texture); + eglDestroyImage(egl_display, image); + + if (!blit_ok) { + return std::nullopt; + } + return std::move(rgb); + } + + std::optional import_source(display_t::pointer egl_display, const surface_descriptor_t &xrgb) { + if (stream_diag_env_enabled("SUNSHINE_STREAM_DIAG_TRY_IMPORT_MATRIX")) { + if (xrgb.fourcc != DRM_FORMAT_XRGB8888) { + BOOST_LOG(warning) << "STREAM_DIAG import matrix skipped" + << " reason=source_fourcc_not_XR24" + << " original_fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc); + } else { + struct import_attempt_t { + std::string_view label; + std::uint32_t fourcc; + GLenum target; + bool include_modifier; + }; + + const import_attempt_t attempts[] { + {"matrix.XR24.2D.modifier"sv, DRM_FORMAT_XRGB8888, GL_TEXTURE_2D, xrgb.modifier != DRM_FORMAT_MOD_INVALID}, + {"matrix.XR24.2D.no_modifier"sv, DRM_FORMAT_XRGB8888, GL_TEXTURE_2D, false}, + {"matrix.AR24.2D.no_modifier"sv, DRM_FORMAT_ARGB8888, GL_TEXTURE_2D, false}, + {"matrix.XR24.external.no_modifier"sv, DRM_FORMAT_XRGB8888, GL_TEXTURE_EXTERNAL_OES, false}, + {"matrix.AR24.external.no_modifier"sv, DRM_FORMAT_ARGB8888, GL_TEXTURE_EXTERNAL_OES, false}, + }; + + for (const auto &attempt : attempts) { + auto rgb = try_import_source_attempt(egl_display, xrgb, attempt.fourcc, attempt.include_modifier, attempt.target, attempt.label); + if (rgb) { + BOOST_LOG(warning) << "STREAM_DIAG import matrix selected successful path" + << " attempt="sv << attempt.label + << " original_fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(attempt.fourcc) + << " target="sv << stream_diag_texture_target_to_string(attempt.target) + << " include_modifiers="sv << attempt.include_modifier; + return rgb; + } + } + + BOOST_LOG(error) << "STREAM_DIAG import matrix failed all attempts" + << " original_fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) + << " width="sv << xrgb.width + << " height="sv << xrgb.height + << " modifier="sv << xrgb.modifier + << " pitch0="sv << xrgb.pitches[0]; + return std::nullopt; + } + } + + const auto import_fourcc = stream_diag_import_fourcc_from_env(xrgb.fourcc); + const auto import_target = stream_diag_import_target_from_env(); + const bool include_modifier = surface_default_include_modifier(xrgb); + + std::string attempt_label {"env."}; + attempt_label += stream_diag_fourcc_to_string(import_fourcc); + attempt_label += '.'; + attempt_label += std::string {stream_diag_texture_target_to_string(import_target)}; + attempt_label += include_modifier ? ".modifier" : ".no_modifier"; + + auto rgb = try_import_source_attempt(egl_display, xrgb, import_fourcc, include_modifier, import_target, attempt_label); + if (rgb) { + BOOST_LOG(info) << "STREAM_DIAG import_source selected successful path" + << " attempt="sv << attempt_label + << " original_fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " target="sv << stream_diag_texture_target_to_string(import_target) + << " include_modifiers="sv << include_modifier; + } return rgb; } @@ -830,8 +1218,8 @@ namespace egl { } std::optional import_target(display_t::pointer egl_display, std::array &&fds, const surface_descriptor_t &y, const surface_descriptor_t &uv) { - auto y_attribs = surface_descriptor_to_egl_attribs(y); - auto uv_attribs = surface_descriptor_to_egl_attribs(uv); + auto y_attribs = surface_descriptor_to_egl_attribs(y, y.fourcc, surface_default_include_modifier(y), "target.y"sv); + auto uv_attribs = surface_descriptor_to_egl_attribs(uv, uv.fourcc, surface_default_include_modifier(uv), "target.uv"sv); nv12_t nv12 { egl_display, From 6425e394079d06cba68dcc1663f604fb89e358ec Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 12 May 2026 23:48:22 -0400 Subject: [PATCH 19/21] Default XR24 KMS import to external texture --- src/platform/linux/graphics.cpp | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/src/platform/linux/graphics.cpp b/src/platform/linux/graphics.cpp index 59e5f215a1c..6600e66d55d 100644 --- a/src/platform/linux/graphics.cpp +++ b/src/platform/linux/graphics.cpp @@ -1155,9 +1155,21 @@ void main() } } + const bool explicit_fourcc_override = !stream_diag_env_value("SUNSHINE_STREAM_DIAG_IMPORT_FOURCC_OVERRIDE").empty(); + const bool explicit_import_target = !stream_diag_env_value("SUNSHINE_STREAM_DIAG_IMPORT_TARGET").empty(); const auto import_fourcc = stream_diag_import_fourcc_from_env(xrgb.fourcc); - const auto import_target = stream_diag_import_target_from_env(); - const bool include_modifier = surface_default_include_modifier(xrgb); + auto import_target = stream_diag_import_target_from_env(); + auto include_modifier = surface_default_include_modifier(xrgb); + + if (!explicit_fourcc_override && !explicit_import_target && xrgb.fourcc == DRM_FORMAT_XRGB8888) { + import_target = GL_TEXTURE_EXTERNAL_OES; + include_modifier = false; + BOOST_LOG(warning) << "STREAM_DIAG defaulting XR24 KMS import to GL_TEXTURE_EXTERNAL_OES with no modifier attrs" + << " original_fourcc="sv << stream_diag_fourcc_to_string(xrgb.fourcc) + << " import_fourcc="sv << stream_diag_fourcc_to_string(import_fourcc) + << " modifier="sv << xrgb.modifier + << " pitch0="sv << xrgb.pitches[0]; + } std::string attempt_label {"env."}; attempt_label += stream_diag_fourcc_to_string(import_fourcc); From aada2f16da525a634c4662efe2a53fa367066bae Mon Sep 17 00:00:00 2001 From: Aedyn Smalley <95597338+NoviceAtPython@users.noreply.github.com> Date: Sat, 16 May 2026 00:52:51 -0400 Subject: [PATCH 20/21] clouddeploy: fix AV1 HDR/10-bit fallback on NVIDIA private DRM path On the CloudDeploy live VM the stream falls to AV1 Main8 / Rec.601 even though the display is scanning out HDR PQ via the patched KWin's NVIDIA private DRM properties. Three independent bugs in the negotiation + encode-selection chain were keeping HDR off; fix all three. 1. kmsgrab `is_hdr()` only saw the standard connector HDR_OUTPUT_METADATA blob. The CloudDeploy KWin patch intentionally leaves that blob at 0 (NVIDIA's atomic check rejects the standard path on the forced/ headless virtual output) and drives NVIDIA private CRTC/plane props instead: CRTC NV_CRTC_REGAMMA_TF = PQ primary plane NV_INPUT_COLORSPACE = BT.2100 PQ primary plane NV_PLANE_DEGAMMA_TF = PQ With is_hdr() returning false, video::colorspace_from_client_config refused to pick bt2020 PQ even when dynamicRange=1 was requested. Patch: add nvidia_private_hdr_active() to kmsgrab's display_t. It walks the active CRTC props for NV_CRTC_REGAMMA_TF==PQ and the active primary plane props for NV_INPUT_COLORSPACE==BT.2100 PQ (also accepting "BT2100 PQ" without the dot, which some nvidia-drm builds emit). Either match returns true. is_hdr() calls this first, so the NVIDIA private path now reports HDR even with hdr_metadata_blob_id==0. get_hdr_metadata() guards the new branch so the per-frame metadata fetch doesn't deref a null optional - the encode pipeline still gets bt2020 PQ colorspace from VUI; only the per-frame infoframe metadata stays unavailable. 2. rtsp `cmd_announce()` parsed `x-nv-video[0].dynamicRangeMode` from the client ANNOUNCE but never reconciled it with the HTTP /launch `hdrMode=` flag stashed in `launch_session->enable_hdr`. The HTTP flag was only used to drive display HDR state. When Moonlight thought the server only advertised AV1 Main8 (see point 3), it would set dynamicRangeMode=0 even when the user had HDR on, and the encode took the 8-bit branch. Patch: after parsing config.monitor.dynamicRange in cmd_announce, if session.enable_hdr is true and dynamicRange came as 0, force it to 1 with a loud INFO log explaining the override. Also: when SUNSHINE_FORCE_AV1_HDR10=1 is set in the environment, do the same override unconditionally (operator/testing knob; the env var was asked for in the CloudDeploy task spec). A new structured log line prints every signal that feeds the encode-selection chain right after the args parse: codec, videoFormat, dynamicRangeMode, encoderCscMode (with csc>>1 and full-range broken out), chromaSamplingType, session.enable_hdr, active_hevc_mode, active_av1_mode. 3. video `probe_encoders()` set active_av1_mode / active_hevc_mode to 3 only when the user-config value was 0 (auto) AND the probe passed DR. Deploy scripts that hardcoded av1_mode=2 (= AV1 enabled, HDR not forced) got stuck at active_av1_mode=2, which clamps ServerCodecModeSupport in /serverinfo to SCM_AV1_MAIN8 only. Moonlight never sees SCM_AV1_MAIN10, never requests HDR. Patch: after the existing auto-resolution, if env SUNSHINE_FORCE_AV1_HDR10=1 is set and the encoder probe just confirmed DYNAMIC_RANGE for HEVC/AV1, bump active_hevc_mode and active_av1_mode from 2 to 3. Leaves user-explicit 1 (disabled) and 3 (enabled-and-DR-required) alone. /serverinfo then advertises SCM_AV1_MAIN10 / SCM_HEVC_MAIN10. New INFO log lines name the chosen modes and per-codec DR support. 4. video `make_encode_device()` now logs the full selection state alongside the existing Color coding / Color depth / Color range lines: codec name, client dynamicRange, disp.is_hdr() result, resolved colorspace, bit depth, selected pix_fmt (NV12 vs P010 vs yuv420p10le), and chromaSamplingType. If client_dynamicRange>0 but the resolved colorspace is not bt2020 PQ, an explicit WARNING points at is_hdr() returning false and the NVIDIA private DRM properties. env vars exposed for CloudDeploy integration --------------------------------------------- * SUNSHINE_FORCE_AV1_HDR10=1 - probe_encoders(): bump active_hevc_mode / active_av1_mode 2 -> 3 when DR probe passed, so /serverinfo advertises SCM_*_MAIN10. - cmd_announce(): force config.monitor.dynamicRange=1 if the client RTSP arg came as 0. Intended use: CloudDeploy sets this when ENABLE_HDR=1 (no sunshine.conf change needed). The fork validates the encoder probe before bumping, so this is safe to leave set permanently. Files changed ------------- src/platform/linux/kmsgrab.cpp - is_hdr() / get_hdr_metadata() NVIDIA private detection src/rtsp.cpp - cmd_announce structured log + session.enable_hdr propagation + SUNSHINE_FORCE_AV1_HDR10 override src/video.cpp - probe_encoders SUNSHINE_FORCE_AV1_HDR10 handler + post-probe summary log - make_encode_device selection log + HDR-not-reached WARNING Expected good-state log markers ------------------------------- On a fresh deploy with ENABLE_HDR=1 + SUNSHINE_FORCE_AV1_HDR10=1, the Sunshine journal should show: is_hdr: NVIDIA private HDR via NV_CRTC_REGAMMA_TF=PQ on CRTC SUNSHINE_FORCE_AV1_HDR10: bumping active_av1_mode 2 -> 3 ... Encoder probe results: active_hevc_mode=3 active_av1_mode=3 ... Client video request: codec=AV1 (videoFormat=2) dynamicRangeMode=1 ... session.enable_hdr=yes active_av1_mode=3 Creating encoder [av1_nvenc] Color coding: HDR (Rec. 2020 + SMPTE 2084 PQ) Color depth: 10-bit Encode selection: codec=AV1 ... selected_pix_fmt=p010 ... Moonlight client log should then show `AV1 actual stream bitdepth 10`. Co-Authored-By: Claude Opus 4.7 --- src/platform/linux/kmsgrab.cpp | 78 ++++++++++++++++++++++++++++++++++ src/rtsp.cpp | 46 ++++++++++++++++++++ src/video.cpp | 56 ++++++++++++++++++++++++ 3 files changed, 180 insertions(+) diff --git a/src/platform/linux/kmsgrab.cpp b/src/platform/linux/kmsgrab.cpp index fedf4aa4716..8ae52d8329b 100644 --- a/src/platform/linux/kmsgrab.cpp +++ b/src/platform/linux/kmsgrab.cpp @@ -1192,7 +1192,73 @@ namespace platf { return 0; } + // Returns true when an NVIDIA private HDR/PQ path is active on the + // selected CRTC or primary plane. The CloudDeploy patched KWin + // intentionally leaves the connector HDR_OUTPUT_METADATA blob at 0 + // (the standard atomic-check path is rejected by NVIDIA on the + // forced/headless virtual output) and instead writes: + // + // CRTC NV_CRTC_REGAMMA_TF = PQ + // primary plane NV_INPUT_COLORSPACE = BT.2100 PQ + // primary plane NV_PLANE_DEGAMMA_TF = PQ + // + // Without this detection, kmsgrab's is_hdr() returns false even + // though the scanout is HDR PQ, and the video::colorspace pipeline + // falls back to SDR. We treat either NV_CRTC_REGAMMA_TF==PQ on the + // active CRTC OR NV_INPUT_COLORSPACE==BT.2100 PQ on the active + // primary plane as sufficient evidence of NVIDIA private HDR. + bool nvidia_private_hdr_active() { + auto find_enum_value = [](const drmModePropertyRes &prop, std::initializer_list wanted) -> std::optional { + for (int i = 0; i < prop.count_enums; ++i) { + std::string_view ename = prop.enums[i].name; + for (auto w : wanted) { + if (ename == w) { + return static_cast(prop.enums[i].value); + } + } + } + return std::nullopt; + }; + + auto enum_prop_matches = [&](const std::vector> &props, std::string_view prop_name, std::initializer_list wanted_enum) -> bool { + for (auto &[prop, val] : props) { + if (!prop || prop->name != prop_name) { + continue; + } + auto want = find_enum_value(*prop, wanted_enum); + if (want && *want == val) { + return true; + } + } + return false; + }; + + if (crtc_id > 0) { + auto cps = card.crtc_props(static_cast(crtc_id)); + if (enum_prop_matches(cps, "NV_CRTC_REGAMMA_TF"sv, {"PQ"sv})) { + BOOST_LOG(info) << "is_hdr: NVIDIA private HDR via NV_CRTC_REGAMMA_TF=PQ on CRTC "sv << crtc_id; + return true; + } + } + if (plane_id > 0) { + auto pps = card.plane_props(static_cast(plane_id)); + if (enum_prop_matches(pps, "NV_INPUT_COLORSPACE"sv, {"BT.2100 PQ"sv, "BT2100 PQ"sv})) { + BOOST_LOG(info) << "is_hdr: NVIDIA private HDR via NV_INPUT_COLORSPACE=BT.2100 PQ on plane "sv << plane_id; + return true; + } + } + return false; + } + bool is_hdr() { + // Check NVIDIA private HDR/PQ path first - the CloudDeploy patched + // KWin uses it instead of the standard connector HDR_OUTPUT_METADATA + // blob, so we must accept it as HDR even when hdr_metadata_blob_id + // is 0. + if (nvidia_private_hdr_active()) { + return true; + } + if (!hdr_metadata_blob_id || *hdr_metadata_blob_id == 0) { return false; } @@ -1244,6 +1310,18 @@ namespace platf { return false; } + // is_hdr() can now return true for the NVIDIA private HDR path + // (no HDR_OUTPUT_METADATA blob; NV_CRTC_REGAMMA_TF=PQ + + // NV_INPUT_COLORSPACE=BT.2100 PQ instead). In that case we have + // no per-frame infoframe metadata to return - the encode pipeline + // still gets bt2020 PQ colorspace from video_colorspace, but + // hdr_info->enabled stays false (the client decodes from + // VUI/sequence header bt2020+SMPTE2084 rather than per-frame). + if (!hdr_metadata_blob_id || *hdr_metadata_blob_id == 0) { + BOOST_LOG(info) << "get_hdr_metadata: HDR active via NVIDIA private path; no per-frame metadata available (encode pipeline will use BT.2020 PQ from VUI)"; + return false; + } + prop_blob_t hdr_metadata_blob = drmModeGetPropertyBlob(card.fd.el, *hdr_metadata_blob_id); if (hdr_metadata_blob == nullptr) { BOOST_LOG(error) << "Unable to get HDR metadata blob: "sv << strerror(errno); diff --git a/src/rtsp.cpp b/src/rtsp.cpp index 9774c791f5d..bdd523df537 100644 --- a/src/rtsp.cpp +++ b/src/rtsp.cpp @@ -1332,6 +1332,52 @@ namespace rtsp_stream { return; } + // Structured client-request log for HDR/codec negotiation diagnosis. + // The previous symptom on the live VM was AV1 8-bit Rec.601 even + // though the display was scanning out HDR PQ via the NVIDIA private + // path. Print every field that feeds video::colorspace_from_client_config + // and the codec/pix_fmt selection so it's obvious which signal is + // wrong when it's wrong. + { + const char *codec_name = (config.monitor.videoFormat == 0) ? "H.264" : + (config.monitor.videoFormat == 1) ? "HEVC" : + (config.monitor.videoFormat == 2) ? "AV1" : + "?"; + BOOST_LOG(info) << "Client video request: codec="sv << codec_name + << " (videoFormat="sv << config.monitor.videoFormat << ')' + << " dynamicRangeMode="sv << config.monitor.dynamicRange + << " encoderCscMode="sv << config.monitor.encoderCscMode + << " (csc>>1="sv << (config.monitor.encoderCscMode >> 1) + << ",fullrange="sv << (config.monitor.encoderCscMode & 0x1) << ')' + << " chromaSamplingType="sv << config.monitor.chromaSamplingType + << " session.enable_hdr="sv << (session.enable_hdr ? "yes"sv : "no"sv) + << " active_hevc_mode="sv << video::active_hevc_mode + << " active_av1_mode="sv << video::active_av1_mode; + } + + // Propagate launch_session.enable_hdr -> config.monitor.dynamicRange. + // + // The HTTP /launch handler parses Moonlight's `hdrMode=` query arg + // into launch_session->enable_hdr, but that flag was only ever used + // to drive display HDR state. Meanwhile the encode pipeline reads + // config.monitor.dynamicRange from a *separate* RTSP arg + // (x-nv-video[0].dynamicRangeMode). When Moonlight thinks the server + // only advertises Main8 (because active_av1_mode<3), it sends + // dynamicRangeMode=0 even though the user enabled HDR on the client. + // If session.enable_hdr is true (HTTP hdrMode=1 was received), force + // the encode pipeline to take the 10-bit branch. + if (session.enable_hdr && config.monitor.dynamicRange == 0) { + BOOST_LOG(info) << "Client HTTP launch set hdrMode=1 but RTSP dynamicRangeMode=0; forcing config.monitor.dynamicRange=1 so encode pipeline takes the 10-bit BT.2020 PQ branch."sv; + config.monitor.dynamicRange = 1; + } + { + auto force_env = std::getenv("SUNSHINE_FORCE_AV1_HDR10"); + if (force_env && std::string_view(force_env) == "1" && config.monitor.dynamicRange == 0) { + BOOST_LOG(info) << "SUNSHINE_FORCE_AV1_HDR10=1 and RTSP dynamicRangeMode=0; forcing config.monitor.dynamicRange=1. The Moonlight client must actually be able to decode 10-bit at the chosen codec or the stream will fail at the client side - this override is an operator/testing knob, not a default."sv; + config.monitor.dynamicRange = 1; + } + } + // When using stereo audio, the audio quality is (strangely) indicated by whether the Host field // in the RTSP message matches a local interface's IP address. Fortunately, Moonlight always sends // 0.0.0.0 when it wants low quality, so it is easy to check without enumerating interfaces. diff --git a/src/video.cpp b/src/video.cpp index 8724e37ebd6..10dba0771b7 100644 --- a/src/video.cpp +++ b/src/video.cpp @@ -2422,6 +2422,11 @@ namespace video { { auto encoder_name = encoder.codec_from_config(config).name; + const char *codec_name = (config.videoFormat == 0) ? "H.264" : + (config.videoFormat == 1) ? "HEVC" : + (config.videoFormat == 2) ? "AV1" : + "?"; + auto pix_fmt_name = platf::from_pix_fmt(pix_fmt); BOOST_LOG(info) << "Creating encoder " << logging::bracket(encoder_name); @@ -2434,6 +2439,22 @@ namespace video { BOOST_LOG(info) << "Color coding: " << color_coding; BOOST_LOG(info) << "Color depth: " << colorspace.bit_depth << "-bit"; BOOST_LOG(info) << "Color range: " << (colorspace.full_range ? "JPEG" : "MPEG"); + // Spell out the entire encode-selection decision so a future + // SDR-fallback regression names itself in the journal: the + // requested codec, the requested dynamicRange, whether the display + // reported HDR (is_hdr_display), the resolved colorspace, the bit + // depth, the encoder pix_fmt (NV12 vs P010 vs yuv420p10le etc.). + BOOST_LOG(info) << "Encode selection: codec="sv << codec_name + << " (videoFormat="sv << config.videoFormat << ')' + << " client_dynamicRange="sv << config.dynamicRange + << " is_hdr_display="sv << (disp.is_hdr() ? "yes"sv : "no"sv) + << " selected_colorspace="sv << color_coding + << " selected_bit_depth="sv << colorspace.bit_depth << "-bit"sv + << " selected_pix_fmt="sv << pix_fmt_name + << " chromaSamplingType="sv << config.chromaSamplingType; + if (config.dynamicRange && colorspace.colorspace != colorspace_e::bt2020) { + BOOST_LOG(warning) << "Client requested HDR (dynamicRange=" << config.dynamicRange << ") but selected colorspace is not BT.2020 PQ. Likely cause: disp.is_hdr() returned false. On the NVIDIA private HDR path, ensure NV_CRTC_REGAMMA_TF=PQ and/or NV_INPUT_COLORSPACE=BT.2100 PQ are set on the active CRTC/plane."; + } } if (dynamic_cast(encoder.platform_formats.get())) { @@ -3207,6 +3228,41 @@ namespace video { active_av1_mode = encoder.av1[encoder_t::PASSED] ? (encoder.av1[encoder_t::DYNAMIC_RANGE] ? 3 : 2) : 1; } + // CloudDeploy override. The user-config av1_mode/hevc_mode value "2" + // means "codec enabled, HDR not forced", which clamps the advertised + // ServerCodecModeSupport to SCM_AV1_MAIN8 / SCM_HEVC_MAIN8 only - even + // when the encoder probe just confirmed DYNAMIC_RANGE = supported. + // Moonlight then sees an SDR-only server, never requests + // dynamicRangeMode=1, and the stream falls to AV1 Main8 / Rec.601. + // When SUNSHINE_FORCE_AV1_HDR10=1 is set and the probe shows DR + // support, bump 2 -> 3 so SCM_AV1_MAIN10 / SCM_HEVC_MAIN10 is + // advertised. This is the lever CloudDeploy flips on ENABLE_HDR=1 + // when it cannot edit sunshine.conf to set av1_mode=0 (auto). + { + auto force_env = std::getenv("SUNSHINE_FORCE_AV1_HDR10"); + bool force = (force_env && std::string_view(force_env) == "1"); + if (force) { + BOOST_LOG(info) << "SUNSHINE_FORCE_AV1_HDR10=1: examining HEVC/AV1 Main10 advertisement"sv; + if (active_hevc_mode == 2 && encoder.hevc[encoder_t::DYNAMIC_RANGE]) { + BOOST_LOG(info) << "SUNSHINE_FORCE_AV1_HDR10: bumping active_hevc_mode 2 -> 3 (encoder ["sv << encoder.name << "] supports HEVC Main10)"sv; + active_hevc_mode = 3; + } else if (active_hevc_mode == 2) { + BOOST_LOG(warning) << "SUNSHINE_FORCE_AV1_HDR10: leaving active_hevc_mode=2 (encoder ["sv << encoder.name << "] HEVC DYNAMIC_RANGE probe = false)"sv; + } + if (active_av1_mode == 2 && encoder.av1[encoder_t::DYNAMIC_RANGE]) { + BOOST_LOG(info) << "SUNSHINE_FORCE_AV1_HDR10: bumping active_av1_mode 2 -> 3 (encoder ["sv << encoder.name << "] supports AV1 Main10)"sv; + active_av1_mode = 3; + } else if (active_av1_mode == 2) { + BOOST_LOG(warning) << "SUNSHINE_FORCE_AV1_HDR10: leaving active_av1_mode=2 (encoder ["sv << encoder.name << "] AV1 DYNAMIC_RANGE probe = false)"sv; + } + } + } + + BOOST_LOG(info) << "Encoder probe results: active_hevc_mode="sv << active_hevc_mode + << " active_av1_mode="sv << active_av1_mode + << " hevc_dr_supported="sv << (encoder.hevc[encoder_t::DYNAMIC_RANGE] ? "yes"sv : "no"sv) + << " av1_dr_supported="sv << (encoder.av1[encoder_t::DYNAMIC_RANGE] ? "yes"sv : "no"sv); + return 0; } From 464bccf1b6e33bf35138136c6138fd9851e6d906 Mon Sep 17 00:00:00 2001 From: Aedyn Smalley <95597338+NoviceAtPython@users.noreply.github.com> Date: Sat, 16 May 2026 03:53:05 -0400 Subject: [PATCH 21/21] clouddeploy: synthesize HDR10 static metadata on NVIDIA private HDR path Symptom on the live VM after the last commit (aada2f16): everything internal to Sunshine is right - the kmsgrab capture detects NVIDIA private HDR, the RTSP cmd_announce path forces dynamicRange=1, make_encode_device picks bt2020 PQ + p010 + 10-bit, NVENC AV1 init succeeds - but the Moonlight client overlay still labels the stream "AV1 10-bit SDR". Root cause: Moonlight derives the overlay HDR/SDR badge from the Sunshine control packet control_hdr_mode_t.enabled, not from the bitstream colour primaries / transfer characteristics. The control packet is built in video::make_synced_session and video::capture_async with this pattern: hdr_info_t hdr_info = std::make_unique(false); if (colorspace_is_hdr(encode_device->colorspace)) { if (disp->get_hdr_metadata(hdr_info->metadata)) { hdr_info->enabled = true; } else { BOOST_LOG(error) << "Couldn't get display hdr metadata when ..."; } } ctx.hdr_events->raise(std::move(hdr_info)); On the CloudDeploy NVIDIA private HDR path, the standard DRM HDR_OUTPUT_METADATA blob is intentionally 0 (the patched KWin uses NV_CRTC_REGAMMA_TF=PQ / NV_INPUT_COLORSPACE=BT.2100 PQ on the active CRTC/plane instead - the standard atomic path is rejected by the NVIDIA driver on the forced/headless virtual output, this is by design and documented in the previous commit). kmsgrab's get_hdr_metadata() correctly returns false there, hdr_info->enabled stays false, stream::send_hdr_mode sends enabled=0, Moonlight shows SDR. Fix: synthesize HDR10 static metadata defaults at every point that currently early-returns on missing display metadata, gated on SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 (the SUNSHINE_FORCE_AV1_HDR10=1 flag already used to bump active_av1_mode 2 -> 3 implies metadata synthesis for symmetry). New helpers in src/video.h + src/video.cpp: void video::populate_default_hdr10_metadata(SS_HDR_METADATA &m); bool video::synthesize_hdr10_metadata_enabled(); Defaults written: BT.2020 primaries (R 0.708/0.292, G 0.170/0.797, B 0.131/0.046), D65 white point (0.3127/0.3290), max luminance 1000 nits, min luminance 0.005 nits (encoded as 50 in 1/10000-nit units per the Sunshine SS_HDR_METADATA protocol extension), MaxCLL 1000, MaxFALL 400, maxFullFrameLuminance 1000. Same general scheme the existing pipewire path uses for SPA BT2020+SMPTE2084 buffers. Patch sites: src/platform/linux/kmsgrab.cpp - display_t::get_hdr_metadata() When is_hdr() returns true via the NVIDIA private path (nvidia_private_hdr_active(); hdr_metadata_blob_id is 0) AND synthesize_hdr10_metadata_enabled(), populate defaults and return true. INFO log line prints every field written. Without the env flag, the existing return-false path stays (with a clearer warning pointing at the flag). src/video.cpp - make_synced_session() + capture_async() inner thread After get_hdr_metadata() fails on a HDR colorspace, if synthesize_hdr10_metadata_enabled(), call populate_default_hdr10_metadata and set hdr_info->enabled = true. INFO log distinguishes "from display" vs "SYNTHESIZED" so the journal makes the source explicit. Else: clearer error pointing at the env flag. This is the belt-and-suspenders fallback in case the capture backend is something other than kmsgrab (pipewire, hypothetically a wlroots backend). src/video.cpp - make_avcodec_encode_session() AVFrame side data Same fallback for AVMasteringDisplayMetadata + AVContentLightMetadata side data. Affects libavcodec encoders (vaapi, software). The native NVENC path already programs primaries/transfer/matrix directly on the AV1 format_config in nvenc_base::create_encoder, so the side data is mostly there for consistency with non-NVENC encoders. INFO logs print has_primaries / has_luminance / maxLum etc. for both synthesized and display-sourced cases. src/stream.cpp - send_hdr_mode() Existing "Sent HDR mode: " debug line bumped to INFO and expanded to print the full metadata summary (enabled, luminance min/max, MaxCLL, MaxFALL, primaries[R], whitePoint). This is the single line that proves Moonlight saw the HDR control packet - invaluable when diagnosing future regressions. src/nvenc/nvenc_base.cpp - create_encoder() After enc_config is populated and just before nvEncInitializeEncoder, log codec / primaries / transfer / matrix / full_range / bit_depth / yuv444. Proves the bitstream colour config will be BT.2020 + SMPTE2084 + limited range + 10-bit + 4:2:0 on the HDR path. env vars (no CloudDeploy changes required for pickup - the existing SUNSHINE_FORCE_AV1_HDR10=1 already does the right thing): SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 - explicit knob SUNSHINE_FORCE_AV1_HDR10=1 - implies synthesis Both accept "1", "true", "TRUE", "yes", "YES" (more forgiving than the strict "1" check on FORCE_AV1_HDR10; either keeps the existing behaviour and adds the new fallback). SDR regression analysis: * All synthesis is gated on colorspace_is_hdr(encode_device->colorspace) AND synthesize_hdr10_metadata_enabled(). Stream with dynamicRange=0 never enters the synthesis branches. * H.264 cannot trigger HDR synthesis: encoder.h264[DYNAMIC_RANGE] is hardcoded to false in probe_encoders() (video.cpp:3005). validate_config rejects HDR-on-H.264 at video.cpp:1859, so colorspace_from_client_config never returns bt2020 for a successfully started H.264 stream. * Encoder probe paths (test_hdr_and_yuv444) call is_codec_supported on the display, which doesn't touch get_hdr_metadata - probe behavior is unchanged. Expected good-state log markers (with SUNSHINE_FORCE_AV1_HDR10=1 or SUNSHINE_SYNTHESIZE_HDR10_METADATA=1): is_hdr: NVIDIA private HDR via NV_INPUT_COLORSPACE=BT.2100 PQ on plane HDR metadata fallback: standard DRM HDR_OUTPUT_METADATA blob is 0 on NVIDIA private HDR path; synthesizing HDR10 static metadata defaults (BT.2020 primaries, D65 white point, max=1000 nits, min=50/10000 nits, MaxCLL=1000, MaxFALL=400) HDR control message (sync session): enabled=1 with SYNTHESIZED HDR10 defaults (...) OR enabled=1 with mastering metadata from display Creating encoder [av1_nvenc] Color coding: HDR (Rec. 2020 + SMPTE 2084 PQ) Color depth: 10-bit selected_pix_fmt=p010 NvEnc color-config: codec=AV1 primaries=9 transfer=16 matrix=9 full_range=0 bit_depth=10 yuv444=no Sent HDR mode control packet to Moonlight: enabled=1 maxDisplayLuminance=1000 nits ... MaxCLL=1000 MaxFALL=400 ... Moonlight client overlay should switch from "AV1 10-bit SDR" to its HDR label after this commit + the env flag is set. If Moonlight still shows SDR after seeing the control packet with enabled=1, the issue is moonlight-stream/moonlight-qt side (overlay caching, decoder negotiation) and not Sunshine - that is detectable because the new "Sent HDR mode control packet" INFO line is the unambiguous server-side ground truth. Files changed ------------- src/video.h - helpers declared src/video.cpp - helpers defined; 3 consumer sites flip to synthesised-fallback path src/platform/linux/kmsgrab.cpp - get_hdr_metadata() synthesises on nvidia_private_hdr + env flag src/stream.cpp - send_hdr_mode log to INFO with full metadata src/nvenc/nvenc_base.cpp - colour-config snapshot log before nvEncInitializeEncoder Co-Authored-By: Claude Opus 4.7 --- src/nvenc/nvenc_base.cpp | 21 +++++++ src/platform/linux/kmsgrab.cpp | 36 +++++++++-- src/stream.cpp | 13 +++- src/video.cpp | 107 ++++++++++++++++++++++++++++++--- src/video.h | 35 +++++++++++ 5 files changed, 198 insertions(+), 14 deletions(-) diff --git a/src/nvenc/nvenc_base.cpp b/src/nvenc/nvenc_base.cpp index ab8aa7a91ff..96ff08fda45 100644 --- a/src/nvenc/nvenc_base.cpp +++ b/src/nvenc/nvenc_base.cpp @@ -422,6 +422,27 @@ namespace nvenc { init_params.encodeConfig = &enc_config; + // Diagnostic snapshot of the colour configuration the NVENC encoder + // is being initialised with. The Moonlight client overlay reads its + // HDR/SDR badge primarily from Sunshine's control_hdr_mode_t packet, + // but if the bitstream-side colour config doesn't match (BT.2020 + + // SMPTE2084 + limited range for HDR10), some clients fall back to + // SDR rendering even after seeing the control flag. Log the actual + // values so a future regression is immediately visible. + { + auto videoFormat_name = client_config.videoFormat == 0 ? "H.264"sv : + client_config.videoFormat == 1 ? "HEVC"sv : + client_config.videoFormat == 2 ? "AV1"sv : + "?"sv; + BOOST_LOG(info) << "NvEnc color-config: codec="sv << videoFormat_name + << " primaries="sv << colorspace.primaries + << " transfer="sv << colorspace.tranfer_function + << " matrix="sv << colorspace.matrix + << " full_range="sv << (int) colorspace.full_range + << " bit_depth="sv << (buffer_is_10bit() ? "10"sv : "8"sv) + << " yuv444="sv << (buffer_is_yuv444() ? "yes"sv : "no"sv); + } + if (nvenc_failed(nvenc->nvEncInitializeEncoder(encoder, &init_params))) { BOOST_LOG(error) << "NvEnc: NvEncInitializeEncoder() failed: " << last_nvenc_error_string; return false; diff --git a/src/platform/linux/kmsgrab.cpp b/src/platform/linux/kmsgrab.cpp index 8ae52d8329b..974bc14867c 100644 --- a/src/platform/linux/kmsgrab.cpp +++ b/src/platform/linux/kmsgrab.cpp @@ -1312,13 +1312,37 @@ namespace platf { // is_hdr() can now return true for the NVIDIA private HDR path // (no HDR_OUTPUT_METADATA blob; NV_CRTC_REGAMMA_TF=PQ + - // NV_INPUT_COLORSPACE=BT.2100 PQ instead). In that case we have - // no per-frame infoframe metadata to return - the encode pipeline - // still gets bt2020 PQ colorspace from video_colorspace, but - // hdr_info->enabled stays false (the client decodes from - // VUI/sequence header bt2020+SMPTE2084 rather than per-frame). + // NV_INPUT_COLORSPACE=BT.2100 PQ instead). In that case the + // standard connector HDR metadata blob is intentionally absent + // (the CloudDeploy patched KWin never sets it because NVIDIA's + // atomic check rejects the standard path on the forced/headless + // virtual output - this is by design, see the comment on + // nvidia_private_hdr_active above). + // + // Without HDR mastering metadata, the Moonlight client overlay + // stays "SDR" even when the bitstream itself carries BT.2020 + + // SMPTE2084 in the AV1 sequence header / HEVC VUI: Moonlight + // derives the overlay state from the Sunshine control packet + // control_hdr_mode_t.enabled, which only gets set to 1 if + // get_hdr_metadata() returns true (see video::make_synced_session + // and video::capture_async in src/video.cpp). + // + // When SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 (or the bundled + // SUNSHINE_FORCE_AV1_HDR10=1 flag), synthesize HDR10 static + // metadata defaults so the control packet, the AVFrame side + // data, and the bitstream all carry consistent HDR signaling. if (!hdr_metadata_blob_id || *hdr_metadata_blob_id == 0) { - BOOST_LOG(info) << "get_hdr_metadata: HDR active via NVIDIA private path; no per-frame metadata available (encode pipeline will use BT.2020 PQ from VUI)"; + if (video::synthesize_hdr10_metadata_enabled()) { + metadata = {}; + video::populate_default_hdr10_metadata(metadata); + BOOST_LOG(info) << "HDR metadata fallback: standard DRM HDR_OUTPUT_METADATA blob is 0 on NVIDIA private HDR path; synthesizing HDR10 static metadata defaults (BT.2020 primaries, D65 white point, max="sv + << metadata.maxDisplayLuminance << " nits, min="sv + << metadata.minDisplayLuminance << "/10000 nits, MaxCLL="sv + << metadata.maxContentLightLevel << ", MaxFALL="sv + << metadata.maxFrameAverageLightLevel << ")"sv; + return true; + } + BOOST_LOG(info) << "get_hdr_metadata: HDR active via NVIDIA private path but standard DRM HDR_OUTPUT_METADATA blob is 0. Set SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 (or SUNSHINE_FORCE_AV1_HDR10=1) to synthesize defaults so Moonlight's HDR overlay reflects the stream state. Without the override, the bitstream still carries BT.2020+SMPTE2084 in the sequence header, but Moonlight's control-protocol HDR signal stays disabled."sv; return false; } diff --git a/src/stream.cpp b/src/stream.cpp index d73694e4ddb..d5940716443 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -1473,7 +1473,18 @@ namespace stream { return -1; } - BOOST_LOG(debug) << "Sent HDR mode: " << hdr_info->enabled; + // INFO-level: this is the control packet Moonlight's overlay reads + // to label the stream as HDR/SDR. If a stream is internally HDR but + // Moonlight still shows SDR, this log line is the diagnostic anchor. + BOOST_LOG(info) << "Sent HDR mode control packet to Moonlight: enabled="sv << (int) hdr_info->enabled + << " maxDisplayLuminance="sv << hdr_info->metadata.maxDisplayLuminance << " nits"sv + << " minDisplayLuminance="sv << hdr_info->metadata.minDisplayLuminance << "/10000 nits"sv + << " MaxCLL="sv << hdr_info->metadata.maxContentLightLevel + << " MaxFALL="sv << hdr_info->metadata.maxFrameAverageLightLevel + << " primaries[R]=("sv << hdr_info->metadata.displayPrimaries[0].x << ',' + << hdr_info->metadata.displayPrimaries[0].y << ')' + << " whitePoint=("sv << hdr_info->metadata.whitePoint.x << ',' + << hdr_info->metadata.whitePoint.y << ')'; return 0; } diff --git a/src/video.cpp b/src/video.cpp index 10dba0771b7..e49f6c6df67 100644 --- a/src/video.cpp +++ b/src/video.cpp @@ -46,6 +46,48 @@ using namespace std::literals; namespace video { + void populate_default_hdr10_metadata(SS_HDR_METADATA &m) { + // BT.2020 primaries (CIE xy, normalized to 50000 per the Sunshine + // protocol extension in moonlight-common-c/Limelight.h): + // R = 0.708, 0.292 + // G = 0.170, 0.797 + // B = 0.131, 0.046 + m.displayPrimaries[0].x = static_cast(0.708f * 50000.0f); + m.displayPrimaries[0].y = static_cast(0.292f * 50000.0f); + m.displayPrimaries[1].x = static_cast(0.170f * 50000.0f); + m.displayPrimaries[1].y = static_cast(0.797f * 50000.0f); + m.displayPrimaries[2].x = static_cast(0.131f * 50000.0f); + m.displayPrimaries[2].y = static_cast(0.046f * 50000.0f); + // D65 white point. + m.whitePoint.x = static_cast(0.3127f * 50000.0f); + m.whitePoint.y = static_cast(0.3290f * 50000.0f); + // Display luminance: + // max = 1000 nits (matches a typical mid-range HDR monitor) + // min = 0.005 nits = 50 in 1/10000-nit units + m.maxDisplayLuminance = 1000; + m.minDisplayLuminance = 50; + // Content light: virtual-headless host has no real source-side + // statistics to draw from; use HDR10 sane defaults so the bitstream + // carries plausible values rather than zero (zero gets the badge + // wrong on some decoders). + m.maxContentLightLevel = 1000; + m.maxFrameAverageLightLevel = 400; + m.maxFullFrameLuminance = 1000; + } + + bool synthesize_hdr10_metadata_enabled() { + auto env_is_true = [](const char *name) { + const char *v = std::getenv(name); + if (!v) { + return false; + } + std::string_view sv {v}; + return sv == "1" || sv == "true" || sv == "TRUE" || sv == "yes" || sv == "YES"; + }; + return env_is_true("SUNSHINE_SYNTHESIZE_HDR10_METADATA") || + env_is_true("SUNSHINE_FORCE_AV1_HDR10"); + } + namespace { std::mutex stream_diag_frame_stats_mutex; std::unordered_map stream_diag_frame_stats_by_channel; @@ -2154,10 +2196,26 @@ namespace video { frame->colorspace = ctx->colorspace; frame->chroma_location = ctx->chroma_sample_location; - // Attach HDR metadata to the AVFrame + // Attach HDR metadata to the AVFrame. Only the libavcodec encoder + // path reads this side data; the native NVENC path (used on the + // CloudDeploy NVIDIA stack) instead programs colorPrimaries / + // transferCharacteristics / matrixCoefficients directly on the AV1 + // format_config in nvenc_base::create_encoder. Both paths share the + // same SS_HDR_METADATA source, so the synthesized-fallback logic + // here keeps libavcodec consumers (vaapi/sw HDR builds) consistent + // with native NVENC. if (colorspace_is_hdr(colorspace)) { SS_HDR_METADATA hdr_metadata; - if (disp->get_hdr_metadata(hdr_metadata)) { + bool have_metadata = disp->get_hdr_metadata(hdr_metadata); + bool synthesized = false; + if (!have_metadata && synthesize_hdr10_metadata_enabled()) { + hdr_metadata = {}; + populate_default_hdr10_metadata(hdr_metadata); + have_metadata = true; + synthesized = true; + BOOST_LOG(info) << "Attaching SYNTHESIZED HDR10 mastering/content-light metadata to AVFrame side data (display reported no metadata; SUNSHINE_SYNTHESIZE_HDR10_METADATA / SUNSHINE_FORCE_AV1_HDR10 active)"sv; + } + if (have_metadata) { auto mdm = av_mastering_display_metadata_create_side_data(frame.get()); mdm->display_primaries[0][0] = av_make_q(hdr_metadata.displayPrimaries[0].x, 50000); @@ -2176,14 +2234,22 @@ namespace video { mdm->has_luminance = hdr_metadata.maxDisplayLuminance != 0 ? 1 : 0; mdm->has_primaries = hdr_metadata.displayPrimaries[0].x != 0 ? 1 : 0; + BOOST_LOG(info) << "Attached AVMasteringDisplayMetadata to frame ("sv + << (synthesized ? "synthesized"sv : "display-sourced"sv) + << "): has_primaries="sv << (int) mdm->has_primaries + << " has_luminance="sv << (int) mdm->has_luminance + << " maxLum="sv << hdr_metadata.maxDisplayLuminance + << " minLum/10000="sv << hdr_metadata.minDisplayLuminance; + if (hdr_metadata.maxContentLightLevel != 0 || hdr_metadata.maxFrameAverageLightLevel != 0) { auto clm = av_content_light_metadata_create_side_data(frame.get()); clm->MaxCLL = hdr_metadata.maxContentLightLevel; clm->MaxFALL = hdr_metadata.maxFrameAverageLightLevel; + BOOST_LOG(info) << "Attached AVContentLightMetadata to frame: MaxCLL="sv << clm->MaxCLL << " MaxFALL="sv << clm->MaxFALL; } } else { - BOOST_LOG(error) << "Couldn't get display hdr metadata when colorspace selection indicates it should have one"; + BOOST_LOG(error) << "AVFrame HDR side data: colorspace is HDR but display returned no mastering metadata and synthesis is disabled. Set SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 to attach HDR10 defaults."; } } @@ -2483,13 +2549,29 @@ namespace video { // absolute mouse coordinates require that the dimensions of the screen are known ctx.touch_port_events->raise(make_port(disp, ctx.config)); - // Update client with our current HDR display state + // Update client with our current HDR display state. + // + // The Moonlight client overlay reads its "HDR/SDR" badge from the + // Sunshine control packet control_hdr_mode_t.enabled (see + // stream::send_hdr_mode). So even if the encoded bitstream itself + // carries BT.2020+SMPTE2084 (AV1 sequence header / HEVC VUI), the + // overlay shows SDR whenever this flag stays false. hdr_info_t hdr_info = std::make_unique(false); if (colorspace_is_hdr(encode_device->colorspace)) { if (disp->get_hdr_metadata(hdr_info->metadata)) { hdr_info->enabled = true; + BOOST_LOG(info) << "HDR control message (sync session): enabled=1 with mastering metadata from display (maxDisplayLuminance="sv << hdr_info->metadata.maxDisplayLuminance << " nits, MaxCLL="sv << hdr_info->metadata.maxContentLightLevel << ", MaxFALL="sv << hdr_info->metadata.maxFrameAverageLightLevel << ")"sv; + } else if (synthesize_hdr10_metadata_enabled()) { + // Display didn't report mastering metadata (NVIDIA private path + // or capture backend without a metadata API). Synthesize sane + // defaults so the control message flips Moonlight's overlay to + // HDR and the bitstream-side metadata is internally consistent. + hdr_info->metadata = {}; + populate_default_hdr10_metadata(hdr_info->metadata); + hdr_info->enabled = true; + BOOST_LOG(info) << "HDR control message (sync session): enabled=1 with SYNTHESIZED HDR10 defaults (display reported no metadata; SUNSHINE_SYNTHESIZE_HDR10_METADATA / SUNSHINE_FORCE_AV1_HDR10 active)"sv; } else { - BOOST_LOG(error) << "Couldn't get display hdr metadata when colorspace selection indicates it should have one"; + BOOST_LOG(error) << "HDR control message (sync session): colorspace is HDR but display returned no mastering metadata and synthesis is disabled. Moonlight overlay will stay SDR. Set SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 to enable defaults."; } } ctx.hdr_events->raise(std::move(hdr_info)); @@ -2754,13 +2836,24 @@ namespace video { // absolute mouse coordinates require that the dimensions of the screen are known touch_port_event->raise(make_port(display.get(), config)); - // Update client with our current HDR display state + // Update client with our current HDR display state. See the + // matching sync-session block above for the rationale: the + // Moonlight overlay reads from control_hdr_mode_t.enabled, so + // this flag must flip true (with at least placeholder metadata) + // even when the display backend can't surface real mastering + // values. hdr_info_t hdr_info = std::make_unique(false); if (colorspace_is_hdr(encode_device->colorspace)) { if (display->get_hdr_metadata(hdr_info->metadata)) { hdr_info->enabled = true; + BOOST_LOG(info) << "HDR control message (async session): enabled=1 with mastering metadata from display (maxDisplayLuminance="sv << hdr_info->metadata.maxDisplayLuminance << " nits, MaxCLL="sv << hdr_info->metadata.maxContentLightLevel << ", MaxFALL="sv << hdr_info->metadata.maxFrameAverageLightLevel << ")"sv; + } else if (synthesize_hdr10_metadata_enabled()) { + hdr_info->metadata = {}; + populate_default_hdr10_metadata(hdr_info->metadata); + hdr_info->enabled = true; + BOOST_LOG(info) << "HDR control message (async session): enabled=1 with SYNTHESIZED HDR10 defaults (display reported no metadata; SUNSHINE_SYNTHESIZE_HDR10_METADATA / SUNSHINE_FORCE_AV1_HDR10 active)"sv; } else { - BOOST_LOG(error) << "Couldn't get display hdr metadata when colorspace selection indicates it should have one"; + BOOST_LOG(error) << "HDR control message (async session): colorspace is HDR but display returned no mastering metadata and synthesis is disabled. Moonlight overlay will stay SDR. Set SUNSHINE_SYNTHESIZE_HDR10_METADATA=1 to enable defaults."; } } hdr_event->raise(std::move(hdr_info)); diff --git a/src/video.h b/src/video.h index 7e180bc2e27..a49bae38647 100644 --- a/src/video.h +++ b/src/video.h @@ -364,6 +364,41 @@ namespace video { using hdr_info_t = std::unique_ptr; + /** + * @brief Populate `metadata` with safe HDR10 static metadata defaults. + * + * Used as a fallback on capture paths where the host display does not + * expose HDR10 mastering display metadata (CIE primaries, white point, + * peak/min luminance) and/or content light metadata (MaxCLL/MaxFALL) + * via the standard system APIs. The CloudDeploy patched KWin NVIDIA + * private HDR path is the motivating case: HDR_OUTPUT_METADATA blob is + * intentionally 0 (the standard atomic-check path is rejected by the + * NVIDIA driver on the forced-headless virtual output), but the + * scanout is genuine HDR PQ via NV_CRTC_REGAMMA_TF / NV_INPUT_COLORSPACE. + * + * Defaults written: + * primaries = BT.2020 (R,G,B) + * white point = D65 + * max luminance = 1000 nits + * min luminance = 0.005 nits (= 50 in 1/10000-nit units) + * MaxCLL = 1000 + * MaxFALL = 400 + * maxFullFrame = 1000 + */ + void populate_default_hdr10_metadata(SS_HDR_METADATA &metadata); + + /** + * @brief Returns true when synthesized HDR10 fallback metadata is allowed. + * + * Reads two env vars (either being "1" enables fallback): + * SUNSHINE_SYNTHESIZE_HDR10_METADATA - preferred explicit knob + * SUNSHINE_FORCE_AV1_HDR10 - already used to bump + * active_av1_mode/hevc_mode to 3; + * implies metadata synthesis + * for symmetry. + */ + bool synthesize_hdr10_metadata_enabled(); + extern int active_hevc_mode; extern int active_av1_mode; extern bool last_encoder_probe_supported_ref_frames_invalidation;