Skip to content
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

Jump to bottom

tracing: make Entered !Send #1001

Merged
merged 5 commits into from
Sep 30, 2020
Merged

tracing: make Entered !Send #1001

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
7eef5d3
tracing: make `Entered` `!Send`
hawkw Sep 29, 2020
89ce4fd
Update examples/examples/hyper-echo.rs
hawkw Sep 29, 2020
81e9e5b
!Send + Sync without unsafe!
hawkw Sep 29, 2020
bdb80e7
Merge branch 'eliza/0.2-api-fixes' of github.com:tokio-rs/tracing int…
hawkw Sep 29, 2020
674aa38
Revert "!Send + Sync without unsafe!"
hawkw Sep 30, 2020
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
126 changes: 61 additions & 65 deletions examples/examples/hyper-echo.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,78 +16,75 @@ async fn echo(req: Request<Body>) -> Result<Response<Body>, hyper::Error> {
uri = ?req.uri(),
headers = ?req.headers()
);
let _enter = span.enter();
info!("received request");
let mut response = Response::new(Body::empty());
async move {
info!("received request");
let mut response = Response::new(Body::empty());

let (rsp_span, resp) = match (req.method(), req.uri().path()) {
// Serve some instructions at /
(&Method::GET, "/") => {
const BODY: &str = "Try POSTing data to /echo";
*response.body_mut() = Body::from(BODY);
(span!(Level::INFO, "response", body = %(&BODY)), response)
}
match (req.method(), req.uri().path()) {
// Serve some instructions at /
(&Method::GET, "/") => {
const BODY: &str = "Try POSTing data to /echo";
*response.body_mut() = Body::from(BODY);
info!(body = %(&BODY), "response",);
Ok(response)
}

// Simply echo the body back to the client.
(&Method::POST, "/echo") => {
let span = span!(Level::INFO, "response", response_kind = %"echo");
*response.body_mut() = req.into_body();
(span, response)
}
// Simply echo the body back to the client.
(&Method::POST, "/echo") => {
info!(response_kind = %"echo", "response");
*response.body_mut() = req.into_body();
Ok(response)
}

// Convert to uppercase before sending back to client.
(&Method::POST, "/echo/uppercase") => {
let body = hyper::body::to_bytes(req).await?;
let upper = body
.iter()
.map(|byte| byte.to_ascii_uppercase())
.collect::<Vec<u8>>();
debug!(
body = ?str::from_utf8(&body[..]),
uppercased = ?str::from_utf8(&upper[..]),
"uppercased request body"
);
// Convert to uppercase before sending back to client.
(&Method::POST, "/echo/uppercase") => {
let body = hyper::body::to_bytes(req).await?;
let upper = body
.iter()
.map(|byte| byte.to_ascii_uppercase())
.collect::<Vec<u8>>();
debug!(
body = ?str::from_utf8(&body[..]),
uppercased = ?str::from_utf8(&upper[..]),
"uppercased request body"
);

*response.body_mut() = Body::from(upper);
(
span!(Level::INFO, "response", response_kind = %"uppercase"),
response,
)
}
info!(response_kind = %"uppercase", "response");
*response.body_mut() = Body::from(upper);
Ok(response)
}

// Reverse the entire body before sending back to the client.
(&Method::POST, "/echo/reversed") => {
let span = span!(Level::TRACE, "response", response_kind = %"reversed");
let _enter = span.enter();
let body = hyper::body::to_bytes(req).await?;
let reversed = body.iter().rev().cloned().collect::<Vec<u8>>();
debug!(
body = ?str::from_utf8(&body[..]),
"reversed request body"
);
*response.body_mut() = Body::from(reversed);
(
span!(Level::INFO, "reversed", body = ?(&response.body())),
response,
)
}
// Reverse the entire body before sending back to the client.
(&Method::POST, "/echo/reversed") => {
async move {
let body = hyper::body::to_bytes(req).await?;
let reversed = body.iter().rev().cloned().collect::<Vec<u8>>();
debug!(
body = ?str::from_utf8(&body[..]),
"reversed request body"
);
*response.body_mut() = Body::from(reversed);
info!( body = ?(&response.body()), "response");
hawkw marked this conversation as resolved.
Show resolved Hide resolved
Ok(response)
}
.instrument(span!(Level::TRACE, "response", response_kind = %"reversed"))
.await
}

// The 404 Not Found route...
_ => {
*response.status_mut() = StatusCode::NOT_FOUND;
(
span!(
Level::TRACE,
"response",
// The 404 Not Found route...
_ => {
*response.status_mut() = StatusCode::NOT_FOUND;
info!(
body = ?(),
status = ?StatusCode::NOT_FOUND,
),
response,
)
"response",
);
Ok(response)
}
}
};
let f = async { resp }.instrument(rsp_span);
Ok(f.await)
}
.instrument(span)
.await
}

#[tokio::main]
Expand All @@ -107,14 +104,13 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {

let local_addr: std::net::SocketAddr = ([127, 0, 0, 1], 3000).into();
let server_span = span!(Level::TRACE, "server", %local_addr);
let _enter = server_span.enter();

let service = make_service_fn(|_| async { Ok::<_, hyper::Error>(service_fn(echo)) });
let server = Server::bind(&local_addr)
.serve(service)
.instrument(server_span.clone());

info!("listening...");
info!(parent: &server_span, "listening...");
server.await?;

Ok(())
Expand Down
37 changes: 35 additions & 2 deletions tracing/src/span.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -318,6 +318,7 @@ pub use tracing_core::span::{Attributes, Id, Record};
use crate::stdlib::{
cmp, fmt,
hash::{Hash, Hasher},
marker::PhantomData,
};
use crate::{
dispatcher::{self, Dispatch},
Expand Down Expand Up @@ -379,6 +380,7 @@ pub(crate) struct Inner {
#[must_use = "once a span has been entered, it should be exited"]
pub struct Entered<'a> {
span: &'a Span,
_not_send: PhantomData<*mut ()>,
Copy link

@MikailBag MikailBag Sep 29, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
_not_send: PhantomData<*mut ()>,
_not_send_but_sync: PhantomData<std::sync::MutexGuard<'static, ()>>,

It's a bit weird, but -1 unsafe, because you don't need to unsafe impl Sync

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oh that's clever! thanks!

unfortunately we can't do exactly what you've suggested, because this needs to compile with the std feature disabled, but I can do something similar.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isn't actually unsafe? We are not dereferencing this type, thus doesn't require unsafe.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@LucioFranco the unsafe was necessary for manually implementing Sync.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

...and, it turns out this approach doesn't actually work in this specific case. Because tracing has conditional support for no_std, we can't use the std::sync version of MutexGuard. I thought we could use the MutexGuard from the spinlock implementation that's used as a fallback on no-std platforms, but I'd forgotten that this is defined in tracing-core, not tracing, and isn't publicly visible. I'll probably go back to the previous approach of just accepting the additional unsafe keyword necessary to manually impl Sync.

}

/// `log` target for all span lifecycle (creation/enter/exit/close) records.
Expand Down Expand Up @@ -562,7 +564,17 @@ impl Span {
/// will call [`Subscriber::exit`]. If the span is disabled, this does
/// nothing.
///
/// # In Asynchronous Code
/// <div class="information">
/// <div class="tooltip ignore" style="">ⓘ<span class="tooltiptext">Note</span></div>
/// </div>
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: The returned
/// <a href="../struct.Entered.html"><code>Entered</code></a> guard does not
/// implement <code>Send</code>. Dropping the guard will exit <em>this</em> span,
/// and if the guard is sent to another thread and dropped there, that thread may
/// never have entered this span. Thus, <code>Entered</code> should not be sent
/// between threads.</pre></div>
///
/// **Warning**: in asynchronous code that uses [async/await syntax][syntax],
/// `Span::enter` should be used very carefully or avoided entirely. Holding
Expand Down Expand Up @@ -755,7 +767,10 @@ impl Span {
}
}}

Entered { span: self }
Entered {
span: self,
_not_send: PhantomData,
}
}

/// Executes the given function in the context of this span.
Expand Down Expand Up @@ -1220,6 +1235,24 @@ impl Clone for Inner {

// ===== impl Entered =====

/// # Safety
///
/// Technically, `Entered` _can_ implement both `Send` *and* `Sync` safely. It
/// doesn't, because it has a `PhantomData<*mut ()>` field, specifically added
/// in order to make it `!Send`.
///
/// Sending an `Entered` guard between threads cannot cause memory unsafety.
/// However, it *would* result in incorrect behavior, so we add a
/// `PhantomData<*mut ()>` to prevent it from being sent between threads. This
/// is because it must be *dropped* on the same thread that it was created;
/// otherwise, the span will never be exited on the thread where it was entered,
/// and it will attempt to exit the span on a thread that may never have entered
/// it. However, we still want them to be `Sync` so that a struct holding an
/// `Entered` guard can be `Sync`.
///
/// Thus, this is totally safe.
unsafe impl<'a> Sync for Entered<'a> {}

impl<'a> Drop for Entered<'a> {
#[inline]
fn drop(&mut self) {
Expand Down