mirrors/actix-web
1
0
Fork 0
mirror of https://github.com/actix/actix-web.git synced 2024-06-02 07:42:41 +00:00
Code Issues Projects Releases Wiki Activity

use tracing in actix-http

Browse source
This commit is contained in:
Rob Ede 2022-03-10 03:12:29 +00:00
parent a03a2a0076
commit 80d222aa78
No known key found for this signature in database
GPG key ID: 97C636207D3EF933
21 changed files with 80 additions and 69 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
actix-http/Cargo.toml
View file

@ -73,11 +73,11 @@ httparse = "1.5.1"
httpdate = "1.0.1"
itoa = "1"
language-tags = "0.3"
log = "0.4"
mime = "0.3"
percent-encoding = "2.1"
pin-project-lite = "0.2"
smallvec = "1.6.1"
tracing = { version = "0.1.30", default-features = false, features = ["log"] }
# http2
h2 = { version = "0.3.9", optional = true }
@ -121,7 +121,7 @@ tokio = { version = "1.8.4", features = ["net", "rt", "macros"] }
[[example]]
name = "ws"
required-features = ["rustls"]
required-features = ["ws", "rustls"]
[[bench]]
name = "write-camel-case"

2
actix-http/README.md
View file

@ -25,7 +25,7 @@ use actix_http::{HttpService, Response};
use actix_server::Server;
use futures_util::future;
use http::header::HeaderValue;
use log::info;
use tracing::info;
#[actix_rt::main]
async fn main() -> io::Result<()> {

3
actix-http/examples/echo.rs
View file

@ -5,6 +5,7 @@ use actix_server::Server;
use bytes::BytesMut;
use futures_util::StreamExt as _;
use http::header::HeaderValue;
use tracing::info;
#[actix_rt::main]
async fn main() -> io::Result<()> {
@ -22,7 +23,7 @@ async fn main() -> io::Result<()> {
body.extend_from_slice(&item?);
}
log::info!("request body: {:?}", body);
info!("request body: {:?}", body);
let res = Response::build(StatusCode::OK)
.insert_header(("x-head", HeaderValue::from_static("dummy value!")))

9
actix-http/examples/hello-world.rs
View file

@ -1,9 +1,8 @@
use std::{convert::Infallible, io, time::Duration};
use actix_http::{
header::HeaderValue, HttpMessage, HttpService, Request, Response, StatusCode,
};
use actix_http::{header::HeaderValue, HttpService, Request, Response, StatusCode};
use actix_server::Server;
use tracing::info;
#[actix_rt::main]
async fn main() -> io::Result<()> {
@ -18,12 +17,12 @@ async fn main() -> io::Result<()> {
ext.insert(42u32);
})
.finish(|req: Request| async move {
log::info!("{:?}", req);
info!("{:?}", req);
let mut res = Response::build(StatusCode::OK);
res.insert_header(("x-head", HeaderValue::from_static("dummy value!")));
let forty_two = req.extensions().get::<u32>().unwrap().to_string();
let forty_two = req.conn_data::<u32>().unwrap().to_string();
res.insert_header((
"x-forty-two",
HeaderValue::from_str(&forty_two).unwrap(),

3
actix-http/examples/streaming-error.rs
View file

@ -12,6 +12,7 @@ use actix_http::{body::BodyStream, HttpService, Response};
use actix_server::Server;
use async_stream::stream;
use bytes::Bytes;
use tracing::info;
#[actix_rt::main]
async fn main() -> io::Result<()> {
@ -21,7 +22,7 @@ async fn main() -> io::Result<()> {
.bind("streaming-error", ("127.0.0.1", 8080), || {
HttpService::build()
.finish(|req| async move {
log::info!("{:?}", req);
info!("{:?}", req);
let res = Response::ok();
Ok::<_, Infallible>(res.set_body(BodyStream::new(stream! {

9
actix-http/examples/ws.rs
View file

@ -17,6 +17,7 @@ use actix_server::Server;
use bytes::{Bytes, BytesMut};
use bytestring::ByteString;
use futures_core::{ready, Stream};
use tracing::{info, trace};
#[actix_rt::main]
async fn main() -> io::Result<()> {
@ -34,13 +35,13 @@ async fn main() -> io::Result<()> {
}
async fn handler(req: Request) -> Result<Response<BodyStream<Heartbeat>>, Error> {
log::info!("handshaking");
info!("handshaking");
let mut res = ws::handshake(req.head())?;
// handshake will always fail under HTTP/2
log::info!("responding");
Ok(res.message_body(BodyStream::new(Heartbeat::new(ws::Codec::new())))?)
info!("responding");
res.message_body(BodyStream::new(Heartbeat::new(ws::Codec::new())))
}
struct Heartbeat {
@ -61,7 +62,7 @@ impl Stream for Heartbeat {
type Item = Result<Bytes, Error>;
fn poll_next(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Option<Self::Item>> {
log::trace!("poll");
trace!("poll");
ready!(self.as_mut().interval.poll_tick(cx));

9
actix-http/src/encoding/encoder.rs
View file

@ -17,6 +17,7 @@ use pin_project_lite::pin_project;
#[cfg(feature = "compress-gzip")]
use flate2::write::{GzEncoder, ZlibEncoder};
use tracing::trace;
#[cfg(feature = "compress-zstd")]
use zstd::stream::write::Encoder as ZstdEncoder;
@ -356,7 +357,7 @@ impl ContentEncoder {
ContentEncoder::Brotli(ref mut encoder) => match encoder.write_all(data) {
Ok(_) => Ok(()),
Err(err) => {
log::trace!("Error decoding br encoding: {}", err);
trace!("Error decoding br encoding: {}", err);
Err(err)
}
},
@ -365,7 +366,7 @@ impl ContentEncoder {
ContentEncoder::Gzip(ref mut encoder) => match encoder.write_all(data) {
Ok(_) => Ok(()),
Err(err) => {
log::trace!("Error decoding gzip encoding: {}", err);
trace!("Error decoding gzip encoding: {}", err);
Err(err)
}
},
@ -374,7 +375,7 @@ impl ContentEncoder {
ContentEncoder::Deflate(ref mut encoder) => match encoder.write_all(data) {
Ok(_) => Ok(()),
Err(err) => {
log::trace!("Error decoding deflate encoding: {}", err);
trace!("Error decoding deflate encoding: {}", err);
Err(err)
}
},
@ -383,7 +384,7 @@ impl ContentEncoder {
ContentEncoder::Zstd(ref mut encoder) => match encoder.write_all(data) {
Ok(_) => Ok(()),
Err(err) => {
log::trace!("Error decoding ztsd encoding: {}", err);
trace!("Error decoding ztsd encoding: {}", err);
Err(err)
}
},

5
actix-http/src/h1/chunked.rs
View file

@ -1,6 +1,7 @@
use std::{io, task::Poll};
use bytes::{Buf as _, Bytes, BytesMut};
use tracing::{debug, trace};
macro_rules! byte (
($rdr:ident) => ({
@ -76,7 +77,7 @@ impl ChunkedState {
Poll::Ready(Ok(ChunkedState::Size))
}
None => {
log::debug!("chunk size would overflow u64");
debug!("chunk size would overflow u64");
Poll::Ready(Err(io::Error::new(
io::ErrorKind::InvalidInput,
"Invalid chunk size line: Size is too big",
@ -124,7 +125,7 @@ impl ChunkedState {
rem: &mut u64,
buf: &mut Option<Bytes>,
) -> Poll<Result<ChunkedState, io::Error>> {
log::trace!("Chunked read, remaining={:?}", rem);
trace!("Chunked read, remaining={:?}", rem);
let len = rdr.len() as u64;
if len == 0 {

2
actix-http/src/h1/decoder.rs
View file

@ -6,7 +6,7 @@ use http::{
header::{self, HeaderName, HeaderValue},
Method, StatusCode, Uri, Version,
};
use log::{debug, error, trace};
use tracing::{debug, error, trace};
use super::chunked::ChunkedState;
use crate::{error::ParseError, header::HeaderMap, ConnectionType, Request, ResponseHead};

49
actix-http/src/h1/dispatcher.rs
View file

@ -15,6 +15,7 @@ use bitflags::bitflags;
use bytes::{Buf, BytesMut};
use futures_core::ready;
use pin_project_lite::pin_project;
use tracing::{debug, error, trace};
use crate::{
body::{BodySize, BoxBody, MessageBody},
@ -336,7 +337,7 @@ where
while written < len {
match io.as_mut().poll_write(cx, &write_buf[written..])? {
Poll::Ready(0) => {
log::error!("write zero; closing");
error!("write zero; closing");
return Poll::Ready(Err(io::Error::new(io::ErrorKind::WriteZero, "")));
}
@ -568,7 +569,7 @@ where
}
StateProj::ExpectCall { fut } => {
log::trace!(" calling expect service");
trace!(" calling expect service");
match fut.poll(cx) {
// expect resolved. write continue to buffer and set InnerDispatcher state
@ -697,12 +698,12 @@ where
let mut this = self.as_mut().project();
if can_not_read {
log::debug!("cannot read request payload");
debug!("cannot read request payload");
if let Some(sender) = &this.payload {
// ...maybe handler does not want to read any more payload...
if let PayloadStatus::Dropped = sender.need_read(cx) {
log::debug!("handler dropped payload early; attempt to clean connection");
debug!("handler dropped payload early; attempt to clean connection");
// ...in which case poll request payload a few times
loop {
match this.codec.decode(this.read_buf)? {
@ -716,7 +717,7 @@ where
// connection is in clean state for next request
Message::Chunk(None) => {
log::debug!("connection successfully cleaned");
debug!("connection successfully cleaned");
// reset dispatcher state
let _ = this.payload.take();
@ -737,7 +738,7 @@ where
// not enough info to decide if connection is going to be clean or not
None => {
log::error!(
error!(
"handler did not read whole payload and dispatcher could not \
drain read buf; return 500 and close connection"
);
@ -813,7 +814,7 @@ where
if let Some(ref mut payload) = this.payload {
payload.feed_data(chunk);
} else {
log::error!("Internal server error: unexpected payload chunk");
error!("Internal server error: unexpected payload chunk");
this.flags.insert(Flags::READ_DISCONNECT);
this.messages.push_back(DispatcherMessage::Error(
Response::internal_server_error().drop_body(),
@ -827,7 +828,7 @@ where
if let Some(mut payload) = this.payload.take() {
payload.feed_eof();
} else {
log::error!("Internal server error: unexpected eof");
error!("Internal server error: unexpected eof");
this.flags.insert(Flags::READ_DISCONNECT);
this.messages.push_back(DispatcherMessage::Error(
Response::internal_server_error().drop_body(),
@ -844,7 +845,7 @@ where
Ok(None) => break,
Err(ParseError::Io(err)) => {
log::trace!("I/O error: {}", &err);
trace!("I/O error: {}", &err);
self.as_mut().client_disconnected();
this = self.as_mut().project();
*this.error = Some(DispatchError::Io(err));
@ -852,7 +853,7 @@ where
}
Err(ParseError::TooLarge) => {
log::trace!("request head was too big; returning 431 response");
trace!("request head was too big; returning 431 response");
if let Some(mut payload) = this.payload.take() {
payload.set_error(PayloadError::Overflow);
@ -872,7 +873,7 @@ where
}
Err(err) => {
log::trace!("parse error {}", &err);
trace!("parse error {}", &err);
if let Some(mut payload) = this.payload.take() {
payload.set_error(PayloadError::EncodingCorrupted);
@ -903,7 +904,7 @@ where
if timer.as_mut().poll(cx).is_ready() {
// timeout on first request (slow request) return 408
log::trace!(
trace!(
"timed out on slow request; \
replying with 408 and closing connection"
);
@ -949,7 +950,7 @@ where
// keep-alive timer has timed out
if timer.as_mut().poll(cx).is_ready() {
// no tasks at hand
log::trace!("timer timed out; closing connection");
trace!("timer timed out; closing connection");
this.flags.insert(Flags::SHUTDOWN);
if let Some(deadline) = this.config.client_disconnect_deadline() {
@ -979,7 +980,7 @@ where
// timed-out during shutdown; drop connection
if timer.as_mut().poll(cx).is_ready() {
log::trace!("timed-out during shutdown");
trace!("timed-out during shutdown");
return Err(DispatchError::DisconnectTimeout);
}
}
@ -1138,12 +1139,12 @@ where
match this.inner.project() {
DispatcherStateProj::Upgrade { fut: upgrade } => upgrade.poll(cx).map_err(|err| {
log::error!("Upgrade handler error: {}", err);
error!("Upgrade handler error: {}", err);
DispatchError::Upgrade
}),
DispatcherStateProj::Normal { mut inner } => {
log::trace!("start flags: {:?}", &inner.flags);
trace!("start flags: {:?}", &inner.flags);
trace_timer_states(
"start",
@ -1250,7 +1251,7 @@ where
// client is gone
if inner.flags.contains(Flags::WRITE_DISCONNECT) {
log::trace!("client is gone; disconnecting");
trace!("client is gone; disconnecting");
return Poll::Ready(Ok(()));
}
@ -1259,14 +1260,14 @@ where
// read half is closed; we do not process any responses
if inner_p.flags.contains(Flags::READ_DISCONNECT) && state_is_none {
log::trace!("read half closed; start shutdown");
trace!("read half closed; start shutdown");
inner_p.flags.insert(Flags::SHUTDOWN);
}
// keep-alive and stream errors
if state_is_none && inner_p.write_buf.is_empty() {
if let Some(err) = inner_p.error.take() {
log::error!("stream error: {}", &err);
error!("stream error: {}", &err);
return Poll::Ready(Err(err));
}
@ -1295,7 +1296,7 @@ where
Poll::Pending
};
log::trace!("end flags: {:?}", &inner.flags);
trace!("end flags: {:?}", &inner.flags);
poll
}
@ -1310,17 +1311,17 @@ fn trace_timer_states(
ka_timer: &TimerState,
shutdown_timer: &TimerState,
) {
log::trace!("{} timers:", label);
trace!("{} timers:", label);
if head_timer.is_enabled() {
log::trace!(" head {}", &head_timer);
trace!(" head {}", &head_timer);
}
if ka_timer.is_enabled() {
log::trace!(" keep-alive {}", &ka_timer);
trace!(" keep-alive {}", &ka_timer);
}
if shutdown_timer.is_enabled() {
log::trace!(" shutdown {}", &shutdown_timer);
trace!(" shutdown {}", &shutdown_timer);
}
}

9
actix-http/src/h1/service.rs
View file

@ -13,6 +13,7 @@ use actix_service::{
};
use actix_utils::future::ready;
use futures_core::future::LocalBoxFuture;
use tracing::error;
use crate::{
body::{BoxBody, MessageBody},
@ -305,13 +306,13 @@ where
Box::pin(async move {
let expect = expect
.await
.map_err(|e| log::error!("Init http expect service error: {:?}", e))?;
.map_err(|e| error!("Init http expect service error: {:?}", e))?;
let upgrade = match upgrade {
Some(upgrade) => {
let upgrade = upgrade
.await
.map_err(|e| log::error!("Init http upgrade service error: {:?}", e))?;
.map_err(|e| error!("Init http upgrade service error: {:?}", e))?;
Some(upgrade)
}
None => None,
@ -319,7 +320,7 @@ where
let service = service
.await
.map_err(|e| log::error!("Init http service error: {:?}", e))?;
.map_err(|e| error!("Init http service error: {:?}", e))?;
Ok(H1ServiceHandler::new(
cfg,
@ -357,7 +358,7 @@ where
fn poll_ready(&self, cx: &mut Context<'_>) -> Poll<Result<(), Self::Error>> {
self._poll_ready(cx).map_err(|err| {
log::error!("HTTP/1 service readiness error: {:?}", err);
error!("HTTP/1 service readiness error: {:?}", err);
DispatchError::Service(err)
})
}

7
actix-http/src/h1/timer.rs
View file

@ -1,6 +1,7 @@
use std::{fmt, future::Future, pin::Pin, task::Context};
use actix_rt::time::{Instant, Sleep};
use tracing::trace;
#[derive(Debug)]
pub(super) enum TimerState {
@ -24,7 +25,7 @@ impl TimerState {
pub(super) fn set(&mut self, timer: Sleep, line: u32) {
if matches!(self, Self::Disabled) {
log::trace!("setting disabled timer from line {}", line);
trace!("setting disabled timer from line {}", line);
}
*self = Self::Active {
@ -39,11 +40,11 @@ impl TimerState {
pub(super) fn clear(&mut self, line: u32) {
if matches!(self, Self::Disabled) {
log::trace!("trying to clear a disabled timer from line {}", line);
trace!("trying to clear a disabled timer from line {}", line);
}
if matches!(self, Self::Inactive) {
log::trace!("trying to clear an inactive timer from line {}", line);
trace!("trying to clear an inactive timer from line {}", line);
}
*self = Self::Inactive;

4
actix-http/src/h2/dispatcher.rs
View file

@ -19,8 +19,8 @@ use h2::{
server::{Connection, SendResponse},
Ping, PingPong,
};
use log::{error, trace};
use pin_project_lite::pin_project;
use tracing::{error, trace, warn};
use crate::{
body::{BodySize, BoxBody, MessageBody},
@ -143,7 +143,7 @@ where
DispatchError::SendResponse(err) => {
trace!("Error sending HTTP/2 response: {:?}", err)
}
DispatchError::SendData(err) => log::warn!("{:?}", err),
DispatchError::SendData(err) => warn!("{:?}", err),
DispatchError::ResponseBody(err) => {
error!("Response payload stream error: {:?}", err)
}

4
actix-http/src/h2/service.rs
View file

@ -14,7 +14,7 @@ use actix_service::{
};
use actix_utils::future::ready;
use futures_core::{future::LocalBoxFuture, ready};
use log::error;
use tracing::{error, trace};
use crate::{
body::{BoxBody, MessageBody},
@ -355,7 +355,7 @@ where
}
Err(err) => {
log::trace!("H2 handshake error: {}", err);
trace!("H2 handshake error: {}", err);
Poll::Ready(Err(err))
}
},

11
actix-http/src/service.rs
View file

@ -15,6 +15,7 @@ use actix_service::{
};
use futures_core::{future::LocalBoxFuture, ready};
use pin_project_lite::pin_project;
use tracing::error;
use crate::{
body::{BoxBody, MessageBody},
@ -369,13 +370,13 @@ where
Box::pin(async move {
let expect = expect
.await
.map_err(|e| log::error!("Init http expect service error: {:?}", e))?;
.map_err(|e| error!("Init http expect service error: {:?}", e))?;
let upgrade = match upgrade {
Some(upgrade) => {
let upgrade = upgrade
.await
.map_err(|e| log::error!("Init http upgrade service error: {:?}", e))?;
.map_err(|e| error!("Init http upgrade service error: {:?}", e))?;
Some(upgrade)
}
None => None,
@ -383,7 +384,7 @@ where
let service = service
.await
.map_err(|e| log::error!("Init http service error: {:?}", e))?;
.map_err(|e| error!("Init http service error: {:?}", e))?;
Ok(HttpServiceHandler::new(
cfg,
@ -490,7 +491,7 @@ where
fn poll_ready(&self, cx: &mut Context<'_>) -> Poll<Result<(), Self::Error>> {
self._poll_ready(cx).map_err(|err| {
log::error!("HTTP service readiness error: {:?}", err);
error!("HTTP service readiness error: {:?}", err);
DispatchError::Service(err)
})
}
@ -666,7 +667,7 @@ where
self.poll(cx)
}
Err(err) => {
log::trace!("H2 handshake error: {}", err);
tracing::trace!("H2 handshake error: {}", err);
Poll::Ready(Err(err))
}
}

3
actix-http/src/ws/codec.rs
View file

@ -2,6 +2,7 @@ use actix_codec::{Decoder, Encoder};
use bitflags::bitflags;
use bytes::{Bytes, BytesMut};
use bytestring::ByteString;
use tracing::error;
use super::{
frame::Parser,
@ -253,7 +254,7 @@ impl Decoder for Codec {
}
}
_ => {
log::error!("Unfinished fragment {:?}", opcode);
error!("Unfinished fragment {:?}", opcode);
Err(ProtocolError::ContinuationFragment(opcode))
}
};

2
actix-http/src/ws/dispatcher.rs
View file

@ -73,8 +73,8 @@ mod inner {
use actix_service::{IntoService, Service};
use futures_core::stream::Stream;
use local_channel::mpsc;
use log::debug;
use pin_project_lite::pin_project;
use tracing::debug;
use actix_codec::{AsyncRead, AsyncWrite, Decoder, Encoder, Framed};

2
actix-http/src/ws/frame.rs
View file

@ -1,7 +1,7 @@
use std::convert::TryFrom;
use bytes::{Buf, BufMut, BytesMut};
use log::debug;
use tracing::debug;
use super::{
mask::apply_mask,

4
actix-http/src/ws/proto.rs
View file

@ -3,6 +3,8 @@ use std::{
fmt,
};
use tracing::error;
/// Operation codes defined in [RFC 6455 §11.8].
///
/// [RFC 6455]: https://datatracker.ietf.org/doc/html/rfc6455#section-11.8
@ -58,7 +60,7 @@ impl From<OpCode> for u8 {
Ping => 9,
Pong => 10,
Bad => {
log::error!("Attempted to convert invalid opcode to u8. This is a bug.");
error!("Attempted to convert invalid opcode to u8. This is a bug.");
8 // if this somehow happens, a close frame will help us tear down quickly
}
}

2
actix-http/tests/test_rustls.rs
View file

@ -212,6 +212,7 @@ async fn h2_content_length() {
let value = HeaderValue::from_static("0");
{
#[allow(clippy::single_element_loop)]
for &i in &[0] {
let req = srv
.request(Method::HEAD, srv.surl(&format!("/{}", i)))
@ -226,6 +227,7 @@ async fn h2_content_length() {
// assert_eq!(response.headers().get(&header), None);
}
#[allow(clippy::single_element_loop)]
for &i in &[1] {
let req = srv
.request(Method::GET, srv.surl(&format!("/{}", i)))

6
actix-web/src/server.rs
View file

@ -367,9 +367,7 @@ where
.local_addr(addr);
let svc = if let Some(handler) = on_connect_fn.clone() {
svc.on_connect_ext(move |io: &_, ext: _| {
(&*handler)(io as &dyn Any, ext)
})
svc.on_connect_ext(move |io: &_, ext: _| (handler)(io as &dyn Any, ext))
} else {
svc
};
@ -555,7 +553,7 @@ where
if let Some(handler) = on_connect_fn.clone() {
svc = svc
.on_connect_ext(move |io: &_, ext: _| (&*handler)(io as &dyn Any, ext));
.on_connect_ext(move |io: &_, ext: _| (handler)(io as &dyn Any, ext));
}
let fac = factory()