feat: log messages from middleware to sentry (#604)

* feat: log messages from middleware to sentry

Actix currently discards any errors generated in the middleware. You are
supposed to pass them in the body or some similar sub-optimal means.

`debug!` statements have been added in the sentry middleware to note if an error has been detected and logged. You can trigger one such error (Bad Hawk Id) by starting a server and trying to fetch from `http://localhost:8000/test`

Closes #504

src/bin/purge_ttl.rs

@@ -8,7 +8,6 @@ use std::time::{Duration, Instant};
 use cadence::{
     BufferedUdpMetricSink, Metric, QueuingMetricSink, StatsdClient, Timed, DEFAULT_PORT,
 };
-
 use googleapis_raw::spanner::v1::{
     spanner::{
         BeginTransactionRequest, CommitRequest, CreateSessionRequest, ExecuteSqlRequest, Session,

src/web/middleware/db.rs

@@ -10,7 +10,9 @@ use futures::future::{self, Either, LocalBoxFuture, Ready, TryFutureExt};
 use std::task::Poll;
 
 use crate::db::params;
+use crate::error::{ApiError, ApiErrorKind};
 use crate::server::{metrics, ServerState};
+use crate::web::middleware::sentry::{queue_report, report};
 use crate::web::{
     extractors::CollectionParam, middleware::SyncServerRequest, tags::Tags, DOCKER_FLOW_ENDPOINTS,
 };
@@ -92,14 +94,16 @@ where
         let state = match &sreq.app_data::<ServerState>() {
             Some(v) => v.clone(),
             None => {
+                let apie: ApiError = ApiErrorKind::NoServerState.into();
+                queue_report(sreq.extensions_mut(), &apie.into());
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::InternalServerError()
                             .content_type("application/json")
                             .body("Err: No State".to_owned())
                             .into_body(),
                     ),
-                ))
+                ));
             }
         };
         let collection = match col_result {
@@ -108,6 +112,7 @@ where
                 // Semi-example to show how to use metrics inside of middleware.
                 metrics::Metrics::from(&state).incr("sync.error.collectionParam");
                 warn!("⚠️ CollectionParam err: {:?}", e);
+                queue_report(sreq.extensions_mut(), &e);
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::InternalServerError()
@@ -123,6 +128,7 @@ where
             Ok(v) => v,
             Err(e) => {
                 warn!("⚠️ Bad Hawk Id: {:?}", e; "user_agent"=> useragent);
+                queue_report(sreq.extensions_mut(), &e);
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::Unauthorized()
@@ -163,7 +169,16 @@ where
                         None => db2.commit(),
                         Some(_) => db2.rollback(),
                     }
-                    .map_err(Into::into)
+                    .map_err(move |apie| {
+                        // we can't queue_report here (no access to extensions)
+                        // so just report it immediately with tags on hand
+                        if apie.is_reportable() {
+                            report(&tags, sentry::integrations::failure::event_from_fail(&apie));
+                        } else {
+                            debug!("Not reporting error: {:?}", apie);
+                        }
+                        apie.into()
+                    })
                     .and_then(|_| future::ok(resp))
                 })
             })

src/web/middleware/mod.rs

@@ -8,8 +8,7 @@ pub mod weave;
 //
 // Matches the [Sync Storage middleware](https://github.com/mozilla-services/server-syncstorage/blob/master/syncstorage/tweens.py) (tweens).
 
-use actix_web::dev::ServiceRequest;
-use actix_web::Error;
+use actix_web::{dev::ServiceRequest, Error};
 
 use crate::db::util::SyncTimestamp;
 use crate::error::{ApiError, ApiErrorKind};

src/web/middleware/precondition.rs

@@ -1,6 +1,7 @@
 use std::task::Context;
 use std::{cell::RefCell, rc::Rc};
 
+use crate::web::middleware::sentry::queue_report;
 use crate::web::{
     extractors::{
         extrude_db, BsoParam, CollectionParam, PreConditionHeader, PreConditionHeaderOpt,
@@ -9,6 +10,7 @@ use crate::web::{
     tags::Tags,
     DOCKER_FLOW_ENDPOINTS, X_LAST_MODIFIED,
 };
+
 use actix_web::{
     dev::{Service, ServiceRequest, ServiceResponse, Transform},
     http::{header, StatusCode},
@@ -95,6 +97,7 @@ where
             },
             Err(e) => {
                 warn!("⚠️ Precondition error {:?}", e);
+                queue_report(sreq.extensions_mut(), &e);
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::BadRequest()
@@ -109,6 +112,7 @@ where
             Ok(v) => v,
             Err(e) => {
                 warn!("⚠️ Hawk header error {:?}", e);
+                queue_report(sreq.extensions_mut(), &e);
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::Unauthorized()
@@ -124,6 +128,7 @@ where
             Ok(v) => v,
             Err(e) => {
                 error!("⚠️ Database access error {:?}", e);
+                queue_report(sreq.extensions_mut(), &e);
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::InternalServerError()
@@ -140,6 +145,7 @@ where
             Ok(v) => v.map(|c| c.collection),
             Err(e) => {
                 warn!("⚠️ Collection Error:  {:?}", e);
+                queue_report(sreq.extensions_mut(), &e);
                 return Box::pin(future::ok(
                     sreq.into_response(
                         HttpResponse::InternalServerError()

src/web/middleware/sentry.rs

@@ -1,11 +1,16 @@
 use std::task::Context;
-use std::{cell::RefCell, rc::Rc};
+use std::{
+    cell::{RefCell, RefMut},
+    rc::Rc,
+};
 
+use actix_http::Extensions;
 use actix_web::{
     dev::{Service, ServiceRequest, ServiceResponse, Transform},
     Error, HttpMessage,
 };
 use futures::future::{self, LocalBoxFuture, TryFutureExt};
+use sentry::protocol::Event;
 use std::task::Poll;
 
 use crate::error::ApiError;
@@ -50,6 +55,32 @@ pub struct SentryWrapperMiddleware<S> {
     service: Rc<RefCell<S>>,
 }
 
+pub fn queue_report(mut ext: RefMut<'_, Extensions>, err: &Error) {
+    let apie: Option<&ApiError> = err.as_error();
+    if let Some(apie) = apie {
+        if !apie.is_reportable() {
+            debug!("Not reporting error: {:?}", err);
+            return;
+        }
+        let event = sentry::integrations::failure::event_from_fail(apie);
+        if let Some(events) = ext.get_mut::<Vec<Event<'static>>>() {
+            events.push(event);
+        } else {
+            let mut events: Vec<Event<'static>> = Vec::new();
+            events.push(event);
+            ext.insert(events);
+        }
+    }
+}
+
+pub fn report(tags: &Tags, mut event: Event<'static>) {
+    let tags = tags.clone();
+    event.tags = tags.clone().tag_tree();
+    event.extra = tags.extra_tree();
+    debug!("Sending error to sentry: {:?}", &event);
+    sentry::capture_event(event);
+}
+
 impl<S, B> Service for SentryWrapperMiddleware<S>
 where
     S: Service<Request = ServiceRequest, Response = ServiceResponse<B>, Error = Error> + 'static,
@@ -70,11 +101,49 @@ where
         let uri = sreq.head().uri.to_string();
         sreq.extensions_mut().insert(tags.clone());
 
-        Box::pin(self.service.call(sreq).and_then(move |sresp| {
+        Box::pin(self.service.call(sreq).and_then(move |mut sresp| {
             // handed an actix_error::error::Error;
-            // Fetch out the tags (in case any have been added.)
+            // Fetch out the tags (in case any have been added.) NOTE: request extensions
+            // are NOT automatically passed to responses. You need to check both.
+            if let Some(t) = sresp.request().extensions().get::<Tags>() {
+                debug!("Found request tags: {:?}", &t.tags);
+                for (k, v) in t.tags.clone() {
+                    tags.tags.insert(k, v);
+                }
+            };
+            if let Some(t) = sresp.response().extensions().get::<Tags>() {
+                debug!("Found response tags: {:?}", &t.tags);
+                for (k, v) in t.tags.clone() {
+                    tags.tags.insert(k, v);
+                }
+            };
+            // add the uri.path (which can cause influx to puke)
+            tags.extra.insert("uri.path".to_owned(), uri);
             match sresp.response().error() {
-                None => {}
+                None => {
+                    // Middleware errors are eaten by current versions of Actix. Errors are now added
+                    // to the extensions. Need to check both for any errors and report them.
+                    if let Some(events) = sresp
+                        .request()
+                        .extensions_mut()
+                        .remove::<Vec<Event<'static>>>()
+                    {
+                        for event in events {
+                            debug!("Found an error in request: {:?}", &event);
+                            report(&tags, event);
+                        }
+                    }
+                    if let Some(events) = sresp
+                        .response_mut()
+                        .extensions_mut()
+                        .remove::<Vec<Event<'static>>>()
+                    {
+                        for event in events {
+                            debug!("Found an error in response: {:?}", &event);
+                            report(&tags, event);
+                        }
+                    }
+                }
                 Some(e) => {
                     let apie: Option<&ApiError> = e.as_error();
                     if let Some(apie) = apie {
@@ -83,33 +152,8 @@ where
                             return future::ok(sresp);
                         }
                     }
-                    // The extensions defined in the request do not get populated
-                    // into the response. There can be two different, and depending
-                    // on where a tag may be set, only one set may be available.
-                    // Base off of the request, then overwrite/suppliment with the
-                    // response.
-                    if let Some(t) = sresp.request().extensions().get::<Tags>() {
-                        debug!("Found request tags: {:?}", &t.tags);
-                        for (k, v) in t.tags.clone() {
-                            tags.tags.insert(k, v);
-                        }
-                    };
-                    if let Some(t) = sresp.response().extensions().get::<Tags>() {
-                        debug!("Found response tags: {:?}", &t.tags);
-                        for (k, v) in t.tags.clone() {
-                            tags.tags.insert(k, v);
-                        }
-                    };
-                    // add the uri.path (which can cause influx to puke)
-                    tags.extra.insert("uri.path".to_owned(), uri);
-                    // deriving the sentry event from a fail directly from the error
-                    // is not currently thread safe. Downcasting the error to an
-                    // ApiError resolves this.
                     if let Some(apie) = apie {
-                        let mut event = sentry::integrations::failure::event_from_fail(apie);
-                        event.tags = tags.clone().tag_tree();
-                        event.extra = tags.extra_tree();
-                        sentry::capture_event(event);
+                        report(&tags, sentry::integrations::failure::event_from_fail(apie));
                     }
                 }
             }