Skip to content

Bug 1652558 - Forward Rust tracing events to the Gecko Profiler, emit neqo_glue logs via tracing #5

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
mxinden-bot wants to merge 2 commits into
base: main
Choose a base branch
from
Open

Bug 1652558 - Forward Rust tracing events to the Gecko Profiler, emit neqo_glue logs via tracing #5

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
41cd84b
Bug 1652558 - Forward Rust tracing events to Gecko logging and the pr…
mxinden Jun 26, 2026
8168430
Bug 2005955 - Emit neqo_glue logs via tracing
mxinden Jun 26, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 4 additions & 1 deletion Cargo.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 1 addition & 1 deletion netwerk/socket/neqo_glue/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ nserror = { path = "../../../xpcom/rust/nserror" }
nsstring = { path = "../../../xpcom/rust/nsstring" }
xpcom = { path = "../../../xpcom/rust/xpcom" }
thin-vec = { version = "0.2.1", features = ["gecko-ffi"] }
log = "0.4.0"
tracing = "0.1"
qlog = "0.16"
libc = "0.2.0"
rustix = { version = "1.1", default-features = false, features = ["fs", "net"] }
Expand Down
77 changes: 51 additions & 26 deletions netwerk/socket/neqo_glue/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,11 +27,10 @@ use firefox_on_glean::{
#[cfg(not(windows))]
use libc::{c_int, AF_INET, AF_INET6};
use libc::{c_uchar, size_t};
use log::debug;
use neqo_common::{
datagram, event::Provider as _, qdebug, qerror, qlog::Qlog, qwarn, Datagram, Decoder, Encoder,
Header, Role, Tos,
datagram, event::Provider as _, qlog::Qlog, Datagram, Decoder, Encoder, Header, Role, Tos,
};
use tracing::{debug, error, warn};
use neqo_http3::{
features::extended_connect::session, ConnectUdpEvent, Error as Http3Error, Http3Client,
Http3ClientEvent, Http3Parameters, Http3State, Priority, WebTransportEvent,
Expand Down Expand Up @@ -241,12 +240,12 @@ fn enable_zstd_decoder(c: &mut Connection) -> neqo_transport::Res<()> {

// ZSTD_isError return 1 if error, 0 otherwise
if unsafe { ZSTD_isError(output_len) != 0 } {
qdebug!("zstd compression failed with {output_len}");
debug!("zstd compression failed with {output_len}");
return Err(nss_rs::Error::CertificateDecoding);
}

if output.len() != output_len {
qdebug!("zstd compression `output_len` {output_len} doesn't match expected `output.len()` {}", output.len());
debug!("zstd compression `output_len` {output_len} doesn't match expected `output.len()` {}", output.len());
return Err(nss_rs::Error::CertificateDecoding);
}

Expand Down Expand Up @@ -370,11 +369,11 @@ impl NeqoHttp3Conn {
let borrowed = {
use std::os::fd::{BorrowedFd, RawFd};
if socket == -1 {
qerror!("got invalid socked {}", socket);
error!("got invalid socked {}", socket);
return Err(NS_ERROR_INVALID_ARG);
}
let raw: RawFd = socket.try_into().map_err(|e| {
qerror!("got invalid socked {}: {}", socket, e);
error!("got invalid socked {}: {}", socket, e);
NS_ERROR_INVALID_ARG
})?;
unsafe { BorrowedFd::borrow_raw(raw) }
Expand All @@ -383,17 +382,17 @@ impl NeqoHttp3Conn {
let borrowed = {
use std::os::windows::io::{BorrowedSocket, RawSocket};
if socket as usize == winapi::um::winsock2::INVALID_SOCKET {
qerror!("got invalid socked {}", socket);
error!("got invalid socked {}", socket);
return Err(NS_ERROR_INVALID_ARG);
}
let raw: RawSocket = socket.try_into().map_err(|e| {
qerror!("got invalid socked {}: {}", socket, e);
error!("got invalid socked {}: {}", socket, e);
NS_ERROR_INVALID_ARG
})?;
unsafe { BorrowedSocket::borrow_raw(raw) }
};
let s = neqo_udp::Socket::new(borrowed).map_err(|e| {
qerror!("failed to initialize socket {}: {}", socket, e);
error!("failed to initialize socket {}: {}", socket, e);
into_nsresult(&e)
})?;
// Called after Socket::new (which sets up IP_RECVTOS etc.) since
Expand Down Expand Up @@ -580,7 +579,7 @@ impl NeqoHttp3Conn {
Err(e) => {
// Emit warnings but to not return an error if qlog initialization
// fails.
qwarn!("failed to create Qlog at {}: {}", qlog_path.display(), e);
warn!("failed to create Qlog at {}: {}", qlog_path.display(), e);
}
}
}
Expand Down Expand Up @@ -683,7 +682,7 @@ impl NeqoHttp3Conn {
glean::http_3_ecn_ce_ect0_ratio_received.accumulate_single_sample_signed(ratio);
} else {
let msg = "Failed to convert ratio to i64 for use with glean";
qwarn!("{msg}");
warn!("{msg}");
debug_assert!(false, "{msg}");
}
}
Expand All @@ -699,14 +698,14 @@ impl NeqoHttp3Conn {
glean::http_3_ecn_ce_ect0_ratio_sent.accumulate_single_sample_signed(ratio);
} else {
let msg = "Failed to convert ratio to i64 for use with glean";
qwarn!("{msg}");
warn!("{msg}");
debug_assert!(false, "{msg}");
}
}
for (outcome, value) in stats.ecn_path_validation.into_iter() {
let Ok(value) = i32::try_from(value) else {
let msg = format!("Failed to convert {value} to i32 for use with glean");
qwarn!("{msg}");
warn!("{msg}");
debug_assert!(false, "{msg}");
continue;
};
Expand Down Expand Up @@ -743,7 +742,7 @@ impl NeqoHttp3Conn {
Some(v)
}
Err(e) => {
qwarn!("Failed to convert ratio to i64 for use with glean: {e}");
warn!("Failed to convert ratio to i64 for use with glean: {e}");
debug_assert!(
false,
"Failed to convert ratio to i64 for use with glean: {e}"
Expand Down Expand Up @@ -931,7 +930,7 @@ impl NeqoHttp3Conn {
.accumulate_single_sample_signed(spurious);
} else {
let msg = "Failed to convert ratio to i64 for use with glean";
qwarn!("{msg}");
warn!("{msg}");
debug_assert!(false, "{msg}");
}
}
Expand All @@ -943,7 +942,7 @@ impl NeqoHttp3Conn {
.add(ce_loss);
} else {
let msg = "Failed to convert to i32 for use with glean";
qwarn!("{msg}");
warn!("{msg}");
debug_assert!(false, "{msg}");
}
if let Ok(ce_ecn) = i32::try_from(stats.cc.congestion_events.ecn) {
Expand All @@ -952,7 +951,7 @@ impl NeqoHttp3Conn {
.add(ce_ecn);
} else {
let msg = "Failed to convert to i32 for use with glean";
qwarn!("{msg}");
warn!("{msg}");
debug_assert!(false, "{msg}");
}
}
Expand Down Expand Up @@ -1141,7 +1140,19 @@ pub struct ProcessInputResult {
pub unsafe extern "C" fn neqo_http3conn_process_input(
conn: &mut NeqoHttp3Conn,
) -> ProcessInputResult {
// Holding this span open for the whole call records an interval (duration)
// marker in the profiler, rather than a point-in-time event. `bytes_received`
// is filled in below once known, and shows up in the marker.
let span =
tracing::debug_span!(
"neqo_http3conn_process_input",
bytes_received = tracing::field::Empty,
segments_received = tracing::field::Empty
)
.entered();

let mut bytes_read = 0;
let mut segments_received: u64 = 0;

RECV_BUF.with_borrow_mut(|recv_buf| {
loop {
Expand All @@ -1157,7 +1168,7 @@ pub unsafe extern "C" fn neqo_http3conn_process_input(
break;
}
Err(e) => {
qwarn!("failed to receive datagrams: {}", e);
warn!("failed to receive datagrams: {}", e);
return ProcessInputResult {
result: into_nsresult(&e),
bytes_read: 0,
Expand Down Expand Up @@ -1189,8 +1200,11 @@ pub unsafe extern "C" fn neqo_http3conn_process_input(
conn.datagram_size_received.accumulate(sum as u64);
conn.datagram_segments_received.accumulate(segment_count);
bytes_read += sum;
segments_received += segment_count;
}

span.record("bytes_received", bytes_read);
span.record("segments_received", segments_received);
ProcessInputResult {
result: NS_OK,
bytes_read: bytes_read.try_into().unwrap_or(u32::MAX),
Expand Down Expand Up @@ -1270,7 +1284,15 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
context: *mut c_void,
set_timer_func: SetTimerFunc,
) -> ProcessOutputAndSendResult {
let span = tracing::debug_span!(
"neqo_http3conn_process_output_and_send",
bytes_sent = tracing::field::Empty,
segments_sent = tracing::field::Empty
)
.entered();

let mut bytes_written: usize = 0;
let mut segments_sent: u64 = 0;
loop {
let Ok(max_gso_segments) = min(
static_prefs::pref!("network.http.http3.max_gso_segments")
Expand All @@ -1282,7 +1304,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
.max_gso_segments(),
)
.try_into() else {
qerror!("Socket return GSO size of 0");
error!("Socket return GSO size of 0");
return ProcessOutputAndSendResult {
result: NS_ERROR_UNEXPECTED,
bytes_written: 0,
Expand All @@ -1306,7 +1328,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
if static_prefs::pref!("network.http.http3.block_loopback_ipv6_addr")
&& matches!(dg.destination(), SocketAddr::V6(addr) if addr.ip().is_loopback())
{
qdebug!("network.http.http3.block_loopback_ipv6_addr is set, returning NS_ERROR_CONNECTION_REFUSED for localhost IPv6");
debug!("network.http.http3.block_loopback_ipv6_addr is set, returning NS_ERROR_CONNECTION_REFUSED for localhost IPv6");
return ProcessOutputAndSendResult {
result: NS_ERROR_CONNECTION_REFUSED,
bytes_written: 0,
Expand All @@ -1318,7 +1340,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
Err(e) if e.kind() == io::ErrorKind::WouldBlock => {
conn.increment_would_block_tx();
if static_prefs::pref!("network.http.http3.pr_poll_write") {
qdebug!("Buffer outbound datagram to be sent once UDP socket has write-availability.");
debug!("Buffer outbound datagram to be sent once UDP socket has write-availability.");
conn.buffered_outbound_datagram = Some(dg);
return ProcessOutputAndSendResult {
// Propagate WouldBlock error, thus indicating that
Expand All @@ -1328,7 +1350,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
bytes_written: bytes_written.try_into().unwrap_or(u32::MAX),
};
} else {
qwarn!("dropping datagram as socket would block");
warn!("dropping datagram as socket would block");
break;
}
}
Expand All @@ -1346,25 +1368,26 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
//
// Long term this fallback belongs in quinn-udp, see
// <https://github.com/quinn-rs/quinn/issues/2399>.
qdebug!("Failed to send datagram batch size {} with error {e}. Missing GSO support? Resending as individual datagrams.", dg.num_datagrams());
debug!("Failed to send datagram batch size {} with error {e}. Missing GSO support? Resending as individual datagrams.", dg.num_datagrams());
let socket = conn.socket.as_mut().expect("non NSPR IO");
for single in dg.iter() {
let single = datagram::Batch::from(single.to_owned());
if let Err(e) = socket.send(&single) {
qwarn!("failed to resend datagram without GSO: {e}");
warn!("failed to resend datagram without GSO: {e}");
break;
}
}
}
Err(e) => {
qwarn!("failed to send datagram: {}", e);
warn!("failed to send datagram: {}", e);
return ProcessOutputAndSendResult {
result: into_nsresult(&e),
bytes_written: 0,
};
}
}
bytes_written += dg.data().len();
segments_sent += dg.num_datagrams() as u64;

// Glean metrics
conn.datagram_size_sent.accumulate(dg.data().len() as u64);
Expand Down Expand Up @@ -1403,6 +1426,8 @@ pub extern "C" fn neqo_http3conn_process_output_and_send(
}
}

span.record("bytes_sent", bytes_written);
span.record("segments_sent", segments_sent);
ProcessOutputAndSendResult {
result: NS_OK,
bytes_written: bytes_written.try_into().unwrap_or(u32::MAX),
Expand Down
13 changes: 13 additions & 0 deletions xpcom/rust/gecko_logger/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,19 @@ fn get_level_for_module<'a>(
return (key, false, LevelFilter::Off);
}

/// Returns whether `target` is enabled at `level` according to the MOZ_LOG
/// module levels. This is the Rust-visible equivalent of `MOZ_LOG_TEST`, for
/// callers (such as the tracing layer) that need to gate work without going
/// through a `log::Record`.
pub fn log_enabled(target: &str, level: Level) -> bool {
if !LOGGING_ACTIVE.load(Ordering::Relaxed) {
return false;
}
let map = LOG_MODULE_MAP.read().unwrap();
let (_, _, filter) = get_level_for_module(&map, target);
filter >= level
}

/// This function takes a record to maybe log to Gecko.
/// It returns true if the record was handled by Gecko's logging, and false
/// otherwise.
Expand Down
3 changes: 3 additions & 0 deletions xpcom/rust/gecko_tracing/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,9 @@ edition = "2021"
license = "MPL-2.0"

[dependencies]
gecko-profiler = { path = "../../../tools/profiler/rust-api" }
gecko_logger = { path = "../gecko_logger" }
log = "0.4"
tracing = "0.1"
tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt", "std"] }
# app-services crates, overridden in the `[patch.crates-io]` section of the top-level Cargo.toml
Expand Down
Loading