Auto merge of #12582 - ehuss:network-target, r=epage

Set tracing target for networking messages.

This changes the log messages for messages related to network traffic to use the "network" tracing target. This makes it easier to do `CARGO_LOG=network=trace CARGO_HTTP_DEBUG=true` instead of trying to figure out which modules to include (and to avoid `CARGO_LOG=trace` which can be too noisy). For example, #12290 moved the location of some log messages to a different module, which broke the documented workflow of using `CARGO_LOG=cargo::ops::registry=debug` to get networking information.
This commit is contained in:
bors 2023-08-28 23:46:05 +00:00
commit 552209137b
6 changed files with 33 additions and 27 deletions

View File

@ -712,7 +712,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
// happen during `wait_for_download`
let token = self.next;
self.next += 1;
debug!("downloading {} as {}", id, token);
debug!(target: "network", "downloading {} as {}", id, token);
assert!(self.pending_ids.insert(id));
let (mut handle, _timeout) = http_handle_and_timeout(self.set.config)?;
@ -731,7 +731,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
crate::try_old_curl_http2_pipewait!(self.set.multiplexing, handle);
handle.write_function(move |buf| {
debug!("{} - {} bytes of data", token, buf.len());
debug!(target: "network", "{} - {} bytes of data", token, buf.len());
tls::with(|downloads| {
if let Some(downloads) = downloads {
downloads.pending[&token]
@ -812,7 +812,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
let (dl, data) = loop {
assert_eq!(self.pending.len(), self.pending_ids.len());
let (token, result) = self.wait_for_curl()?;
debug!("{} finished with {:?}", token, result);
debug!(target: "network", "{} finished with {:?}", token, result);
let (mut dl, handle) = self
.pending
@ -873,7 +873,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
return Err(e.context(format!("failed to download from `{}`", dl.url)))
}
RetryResult::Retry(sleep) => {
debug!("download retry {} for {sleep}ms", dl.url);
debug!(target: "network", "download retry {} for {sleep}ms", dl.url);
self.sleeping.push(sleep, (dl, handle));
}
}
@ -969,7 +969,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
.perform()
.with_context(|| "failed to perform http requests")
})?;
debug!("handles remaining: {}", n);
debug!(target: "network", "handles remaining: {}", n);
let results = &mut self.results;
let pending = &self.pending;
self.set.multi.messages(|msg| {
@ -978,7 +978,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
if let Some(result) = msg.result_for(handle) {
results.push((token, result));
} else {
debug!("message without a result (?)");
debug!(target: "network", "message without a result (?)");
}
});
@ -988,7 +988,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
assert_ne!(self.remaining(), 0);
if self.pending.is_empty() {
let delay = self.sleeping.time_to_next().unwrap();
debug!("sleeping main thread for {delay:?}");
debug!(target: "network", "sleeping main thread for {delay:?}");
std::thread::sleep(delay);
} else {
let min_timeout = Duration::new(1, 0);

View File

@ -335,7 +335,7 @@ impl<'cfg> HttpRegistry<'cfg> {
}),
RetryResult::Err(e) => Err(e),
RetryResult::Retry(sleep) => {
debug!("download retry {:?} for {sleep}ms", download.path);
debug!(target: "network", "download retry {:?} for {sleep}ms", download.path);
self.downloads.sleeping.push(sleep, (download, handle));
continue;
}
@ -551,7 +551,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
&& path == Path::new(RegistryConfig::NAME)
&& self.config.cli_unstable().registry_auth =>
{
debug!("re-attempting request for config.json with authorization included.");
debug!(target: "network", "re-attempting request for config.json with authorization included.");
self.fresh.remove(path);
self.auth_required = true;
@ -568,9 +568,11 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
}
}
Ok(challenge) => {
debug!("ignoring non-Cargo challenge: {}", challenge.scheme)
debug!(target: "network", "ignoring non-Cargo challenge: {}", challenge.scheme)
}
Err(e) => {
debug!(target: "network", "failed to parse challenge: {}", e)
}
Err(e) => debug!("failed to parse challenge: {}", e),
}
}
}
@ -618,7 +620,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
let mut handle = http_handle(self.config)?;
let full_url = self.full_url(path);
debug!("fetch {}", full_url);
debug!(target: "network", "fetch {}", full_url);
handle.get(true)?;
handle.url(&full_url)?;
handle.follow_location(true)?;
@ -653,7 +655,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
self.auth_error_headers.clone(),
)?;
headers.append(&format!("Authorization: {}", authorization))?;
trace!("including authorization for {}", full_url);
trace!(target: "network", "including authorization for {}", full_url);
}
handle.http_headers(headers)?;
@ -662,7 +664,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
// We do that through this token. Each request (and associated response) gets one.
let token = self.downloads.next;
self.downloads.next += 1;
debug!("downloading {} as {}", path.display(), token);
debug!(target: "network", "downloading {} as {}", path.display(), token);
let is_new = self.downloads.pending_paths.insert(path.to_path_buf());
assert!(is_new, "path queued for download more than once");
@ -671,7 +673,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
// That thread-local is set up in `block_until_ready` when it calls self.multi.perform,
// which is what ultimately calls this method.
handle.write_function(move |buf| {
trace!("{} - {} bytes of data", token, buf.len());
trace!(target: "network", "{} - {} bytes of data", token, buf.len());
tls::with(|downloads| {
if let Some(downloads) = downloads {
downloads.pending[&token]
@ -772,7 +774,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
}
fn block_until_ready(&mut self) -> CargoResult<()> {
trace!(
trace!(target: "network",
"block_until_ready: {} transfers pending",
self.downloads.pending.len()
);
@ -787,7 +789,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
.perform()
.with_context(|| "failed to perform http requests")
})?;
trace!("{} transfers remaining", remaining_in_multi);
trace!(target: "network", "{} transfers remaining", remaining_in_multi);
if remaining_in_multi + self.downloads.sleeping.len() as u32 == 0 {
return Ok(());
@ -795,7 +797,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
if self.downloads.pending.is_empty() {
let delay = self.downloads.sleeping.time_to_next().unwrap();
debug!("sleeping main thread for {delay:?}");
debug!(target: "network", "sleeping main thread for {delay:?}");
std::thread::sleep(delay);
} else {
// We have no more replies to provide the caller with,

View File

@ -135,7 +135,7 @@ pub fn configure_http_handle(config: &Config, handle: &mut Easy) -> CargoResult<
if let Some(true) = http.debug {
handle.verbose(true)?;
tracing::debug!("{:#?}", curl::Version::get());
tracing::debug!(target: "network", "{:#?}", curl::Version::get());
handle.debug_function(|kind, data| {
enum LogLevel {
Debug,
@ -167,16 +167,20 @@ pub fn configure_http_handle(config: &Config, handle: &mut Easy) -> CargoResult<
line = "set-cookie: [REDACTED]";
}
match level {
Debug => debug!("http-debug: {prefix} {line}"),
Trace => trace!("http-debug: {prefix} {line}"),
Debug => debug!(target: "network", "http-debug: {prefix} {line}"),
Trace => trace!(target: "network", "http-debug: {prefix} {line}"),
}
}
}
Err(_) => {
let len = data.len();
match level {
Debug => debug!("http-debug: {prefix} ({len} bytes of data)"),
Trace => trace!("http-debug: {prefix} ({len} bytes of data)"),
Debug => {
debug!(target: "network", "http-debug: {prefix} ({len} bytes of data)")
}
Trace => {
trace!(target: "network", "http-debug: {prefix} ({len} bytes of data)")
}
}
}
}

View File

@ -29,7 +29,7 @@ macro_rules! try_old_curl {
let result = $e;
if cfg!(target_os = "macos") {
if let Err(e) = result {
::tracing::warn!("ignoring libcurl {} error: {}", $msg, e);
::tracing::warn!(target: "network", "ignoring libcurl {} error: {}", $msg, e);
}
} else {
use ::anyhow::Context;

View File

@ -16,7 +16,7 @@ CARGO_LOG=debug cargo generate-lockfile
CARGO_LOG=cargo::core::resolver=trace cargo generate-lockfile
# This will print lots of info about the download process. `trace` prints even more.
CARGO_HTTP_DEBUG=true CARGO_LOG=cargo::ops::registry=debug cargo fetch
CARGO_HTTP_DEBUG=true CARGO_LOG=network=debug cargo fetch
# This is an important command for diagnosing fingerprint issues.
CARGO_LOG=cargo::core::compiler::fingerprint=trace cargo build

View File

@ -622,8 +622,8 @@ crate dependencies and accessing remote git repositories.
* Environment: `CARGO_HTTP_DEBUG`
If `true`, enables debugging of HTTP requests. The debug information can be
seen by setting the `CARGO_LOG=cargo::ops::registry=debug` environment
variable (or use `trace` for even more information).
seen by setting the `CARGO_LOG=network=debug` environment
variable (or use `network=trace` for even more information).
Be wary when posting logs from this output in a public location. The output
may include headers with authentication tokens which you don't want to leak!