actix-web: Middleware Logger not logging errors thrown by middleware

I have a middleware to check for payments.

It has signature

impl<S> Transform<S> for CheckPayment
where
    S: Service<Request = ServiceRequest, Response = ServiceResponse<Body>, Error = Error>,
    S::Future: 'static,
{
    type Request = ServiceRequest;
    type Response = ServiceResponse<Body>;
    type Error = Error;
    type InitError = ();
    type Transform = CheckPaymentMiddleware<S>;
    type Future = FutureResult<Self::Transform, Self::InitError>;
pub struct CheckPayment(BitcoinClient, WalletState);

impl CheckPayment {
    pub fn new(client: BitcoinClient, wallet_state: WalletState) -> Self {
        CheckPayment(client, wallet_state)
    }
}

impl<S> Transform<S> for CheckPayment
where
    S: Service<Request = ServiceRequest, Response = ServiceResponse<Body>, Error = Error>,
    S::Future: 'static,
{
    type Request = ServiceRequest;
    type Response = ServiceResponse<Body>;
    type Error = Error;
    type InitError = ();
    type Transform = CheckPaymentMiddleware<S>;
    type Future = FutureResult<Self::Transform, Self::InitError>;

and have an ServerError enum which implements error::ResponseError.

During the CheckPaymentMiddleware call function errors can are thrown and converted as follows: return Box::new(err(ServerError::Payment(PaymentError::InvalidAuth).into())).

The errors are picked up by actix_http

[2019-08-23T12:58:18Z ERROR actix_http::response] Internal Server Error: Payment(AddrFetchFailed)

but are not picked up by the logger (and hence aren’t formatted with important information) which is instantiated as follows:

        App::new()
            .wrap(Logger::default())
            .wrap(Logger::new("%a %{User-Agent}i"))
            .service(
                // Key scope
                web::scope("/keys").service(
                    web::resource("/{addr}")
                        .data(key_db_inner)
                        .wrap(CheckPayment::new(
                            bitcoin_client_inner.clone(),
                            wallet_state_inner.clone(),
                        )) // Apply payment check to put key
                        .route(web::get().to(get_key))
                        .route(web::put().to_async(put_key)),
                ),
            )

Is this expected behavior? How do I pass the error through to the outer logging middleware?

About this issue

  • Original URL
  • State: closed
  • Created 5 years ago
  • Comments: 21 (10 by maintainers)

Most upvoted comments

+1

https://httpd.apache.org/docs/2.4/logs.html#accesslog https://docs.nginx.com/nginx/admin-guide/monitoring/logging/#setting-up-the-access-log

The server access log records all requests processed by the server.

Can we consider reopening the issue?

Can we consider reopening this issue?

Middleware is how every request and response is handled. To eat Errors and only allow response bodies can lead to some fairly atrocious hacks, particularly when dealing with reporting systems like Sentry. I have to be super mindful when I log an error inside of any middleware processor to include it in the response data state and then have my sentry reporting middleware check for that state entry, and even that won’t capture every event because there could be some that slip by.

If there’s a better pattern for this, I’m happy to implement one.

I would also like to see this issue reopened as I find this behaviour to be unintuitive and unergonomic. I am experiencing a problem similar to that of the author of this issue. I have a middleware that can succeed or fail - I read the Authentication header from the request and parse the value and validate it. On a successful parse/validation, I modify the request extensions; on fail, I respond with an error message. However, such requests where the failure occurs are never logged, as if they never happened.

Currently, the alternative is not to use middleware, and to do this verification step at each endpoint. This defeats the purpose of middleware, and creates a high maintenance toll. Logging requests where the response is generated by the middleware would be very helpful.

+1 on reopening. Not getting a response logged when it happened to originate from an Err condition in middleware is unexpected behavior at best.

@hlb8122 did you register logger as last middleware?