diff --git a/README.md b/README.md index 5b45ecd9..08eee669 100644 --- a/README.md +++ b/README.md @@ -32,6 +32,10 @@ and can be run against a local server, e.g.: $ export SYNC_DATABASE_URL=mysql://:@localhost/syncstorage $ cargo run +## Logging + +If you want to connect to the existing [Sentry project](https://sentry.prod.mozaws.net/operations/syncstorage-dev/) for local development, login to Sentry, and go to the page with [api keys](https://sentry.prod.mozaws.net/settings/operations/syncstorage-dev/keys/). Copy the `DSN` value, and `export SENTRY_DSN=DSN_VALUE_GOES_HERE` to the environment when running this project. + ## Running the Unit tests 1) Run: diff --git a/db-tests/Cargo.lock b/db-tests/Cargo.lock index 0c2be732..17b09aec 100644 --- a/db-tests/Cargo.lock +++ b/db-tests/Cargo.lock @@ -645,10 +645,11 @@ name = "db-tests" version = "0.1.0" dependencies = [ "codegen 0.1.0", - "env_logger 0.6.2 (registry+https://github.com/rust-lang/crates.io-index)", + "env_logger 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", "futures-preview 0.3.0-alpha.16 (git+https://github.com/rust-lang-nursery/futures-rs?rev=744ece9)", "lazy_static 1.4.0 (registry+https://github.com/rust-lang/crates.io-index)", - "rand 0.6.5 (registry+https://github.com/rust-lang/crates.io-index)", + "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", "syncstorage 0.1.0", ] @@ -796,6 +797,18 @@ dependencies = [ "termcolor 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)", ] +[[package]] +name = "env_logger" +version = "0.7.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +dependencies = [ + "atty 0.2.13 (registry+https://github.com/rust-lang/crates.io-index)", + "humantime 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)", + "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", + "regex 1.3.1 (registry+https://github.com/rust-lang/crates.io-index)", + "termcolor 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)", +] + [[package]] name = "erased-serde" version = "0.3.9" @@ -3077,6 +3090,7 @@ dependencies = [ "checksum encoding_rs 0.8.20 (registry+https://github.com/rust-lang/crates.io-index)" = "87240518927716f79692c2ed85bfe6e98196d18c6401ec75355760233a7e12e9" "checksum enum-as-inner 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "3d58266c97445680766be408285e798d3401c6d4c378ec5552e78737e681e37d" "checksum env_logger 0.6.2 (registry+https://github.com/rust-lang/crates.io-index)" = "aafcde04e90a5226a6443b7aabdb016ba2f8307c847d524724bd9b346dd1a2d3" +"checksum env_logger 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)" = "39ecdb7dd54465526f0a56d666e3b2dd5f3a218665a030b6e4ad9e70fa95d8fa" "checksum erased-serde 0.3.9 (registry+https://github.com/rust-lang/crates.io-index)" = "3beee4bc16478a1b26f2e80ad819a52d24745e292f521a63c16eea5f74b7eb60" "checksum error-chain 0.12.1 (registry+https://github.com/rust-lang/crates.io-index)" = "3ab49e9dcb602294bc42f9a7dfc9bc6e936fca4418ea300dbfb84fe16de0b7d9" "checksum failure 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "795bd83d3abeb9220f257e597aa0080a508b27533824adf336529648f6abf7e2" diff --git a/db-tests/Cargo.toml b/db-tests/Cargo.toml index f3e521dc..96909d51 100644 --- a/db-tests/Cargo.toml +++ b/db-tests/Cargo.toml @@ -6,9 +6,10 @@ edition = "2018" [dependencies] codegen = { version = "0.1.0", path = "../codegen" } -env_logger = "0.6.1" +env_logger = "0.7.0" futures-preview = { git = "https://github.com/rust-lang-nursery/futures-rs", rev = "744ece9", features = ["compat"] } -lazy_static = "1.3.0" -rand = "0.6.5" +lazy_static = "1.4.0" +log="0.4" +rand = "0.7.2" syncstorage = { version = "0.1.0", path = "../", features = ["db_test"] } diff --git a/db-tests/src/batch.rs b/db-tests/src/batch.rs index f6dc10de..a78dd60d 100644 --- a/db-tests/src/batch.rs +++ b/db-tests/src/batch.rs @@ -1,6 +1,8 @@ use futures::compat::Future01CompatExt; use codegen::async_test; +use log::debug; + use syncstorage::{ db::{error::DbErrorKind, params, util::SyncTimestamp, BATCH_LIFETIME}, error::ApiErrorKind, @@ -141,7 +143,7 @@ async fn append_commit() -> Result<()> { .compat() .await?; - dbg!("result", &result); + debug!("result: {:?}", &result); assert!(result.success.contains(&"b0".to_owned())); assert!(result.success.contains(&"b2".to_owned())); diff --git a/spanner-2019-10-01.ddl b/spanner-2019-10-01.ddl index 19912d23..2a10e263 100644 --- a/spanner-2019-10-01.ddl +++ b/spanner-2019-10-01.ddl @@ -1,21 +1,29 @@ +-- fxa_uid: a 16 byte identifier, randomly generated by the fxa server +-- usually a UUID, so presuming a formatted form. +-- fxa_kid: <`mono_num`>-<`client_state`> +-- +-- - mono_num: a monotonically increasing timestamp or generation number +-- in hex and padded to 13 digits, provided by the fxa server +-- - client_state: the first 16 bytes of a SHA256 hash of the user's sync +-- encryption key. +-- +-- NOTE: DO NOT INCLUDE COMMENTS IF PASTING INTO CONSOLE +-- ALSO, CONSOLE WANTS ONE SPACE BETWEEN DDL COMMANDS + CREATE TABLE user_collections ( - fxa_uid STRING(MAX) NOT NULL, - fxa_kid STRING(MAX) NOT NULL, + fxa_uid STRING(36) NOT NULL, + fxa_kid STRING(48) NOT NULL, collection_id INT64 NOT NULL, modified TIMESTAMP NOT NULL, ) PRIMARY KEY(fxa_uid, fxa_kid, collection_id); - CREATE TABLE bso ( - fxa_uid STRING(MAX) NOT NULL, - fxa_kid STRING(MAX) NOT NULL, + fxa_uid STRING(36) NOT NULL, + fxa_kid STRING(48) NOT NULL, collection_id INT64 NOT NULL, - id STRING(MAX) NOT NULL, - + id STRING(64) NOT NULL, sortindex INT64, - payload STRING(MAX) NOT NULL, - modified TIMESTAMP NOT NULL, expiry TIMESTAMP NOT NULL, ) PRIMARY KEY(fxa_uid, fxa_kid, collection_id, id), @@ -28,19 +36,17 @@ INTERLEAVE IN user_collections; CREATE INDEX BsoExpiry ON bso(expiry); - CREATE TABLE collections ( id INT64 NOT NULL, - name STRING(MAX) NOT NULL, + name STRING(32) NOT NULL, ) PRIMARY KEY(id); CREATE UNIQUE INDEX CollectionName ON collections(name); - CREATE TABLE batches ( - fxa_uid STRING(MAX) NOT NULL, - fxa_kid STRING(MAX) NOT NULL, + fxa_uid STRING(36) NOT NULL, + fxa_kid STRING(48) NOT NULL, id TIMESTAMP NOT NULL, collection_id INT64 NOT NULL, bsos STRING(MAX) NOT NULL, diff --git a/src/db/spanner/models.rs b/src/db/spanner/models.rs index 29a7a95b..fa60d435 100644 --- a/src/db/spanner/models.rs +++ b/src/db/spanner/models.rs @@ -2,6 +2,7 @@ use futures::future; use futures::lazy; use diesel::r2d2::PooledConnection; +use log::debug; use std::cell::RefCell; use std::collections::HashMap; @@ -439,7 +440,10 @@ impl SpannerDb { &self, params: params::GetCollectionTimestamp, ) -> Result { - dbg!("!!QQQ get_collection_timestamp_sync", ¶ms.collection); + debug!( + "!!QQQ get_collection_timestamp_sync {:?}", + ¶ms.collection + ); let collection_id = self.get_collection_id(¶ms.collection)?; if let Some(modified) = self @@ -1005,7 +1009,7 @@ impl SpannerDb { } pub fn get_bso_timestamp_sync(&self, params: params::GetBsoTimestamp) -> Result { - dbg!("!!QQQ get_bso_timestamp_sync", ¶ms.collection); + debug!("!!QQQ get_bso_timestamp_sync: {:?}", ¶ms.collection); let collection_id = self.get_collection_id(¶ms.collection)?; let result = self @@ -1099,7 +1103,7 @@ impl SpannerDb { } if !inserts.is_empty() { - dbg!(&inserts); + debug!("inserts: {:?}", &inserts); self.insert( "bso", &[ @@ -1116,7 +1120,7 @@ impl SpannerDb { ); } for (columns, values) in updates { - dbg!(&columns, &values); + debug!("columns: {:?}, values:{:?}", &columns, &values); self.update("bso", &columns, values); } @@ -1266,7 +1270,10 @@ impl SpannerDb { .map_or(i64::from(DEFAULT_BSO_TTL), |ttl| ttl.try_into().unwrap()) * 1000; let expirystring = to_rfc3339(now_millis + ttl)?; - dbg!("!!!!! INSERT", &expirystring, timestamp, ttl); + debug!( + "!!!!! INSERT expirystring:{:?}, timestamp:{:?}, ttl:{:?}", + &expirystring, timestamp, ttl + ); sqlparams.insert("expiry".to_string(), as_value(expirystring)); sqltypes.insert("expiry".to_string(), SpannerType::Timestamp.into()); diff --git a/src/main.rs b/src/main.rs index 006ac1f5..84ee4e61 100644 --- a/src/main.rs +++ b/src/main.rs @@ -2,7 +2,7 @@ use std::error::Error; use docopt::Docopt; -use log::info; +use log::{debug, info}; use serde_derive::Deserialize; use syncstorage::{logging, server, settings}; @@ -22,6 +22,7 @@ struct Args { fn main() -> Result<(), Box> { env_logger::init(); + debug!("Starting up..."); // Set SENTRY_DSN environment variable to enable Sentry let sentry = sentry::init(sentry::ClientOptions::default()); if sentry.is_enabled() { diff --git a/src/server/metrics.rs b/src/server/metrics.rs index d3d15d2f..d355b2c8 100644 --- a/src/server/metrics.rs +++ b/src/server/metrics.rs @@ -2,6 +2,7 @@ use std::net::UdpSocket; use actix_web::{error::ErrorInternalServerError, Error, HttpRequest}; use cadence::{BufferedUdpMetricSink, Counted, NopMetricSink, QueuingMetricSink, StatsdClient}; +use log::debug; use crate::error::ApiError; use crate::server::ServerState; @@ -18,7 +19,7 @@ impl From<&HttpRequest> for Metrics { client: match req.app_data::() { Some(v) => Some(*v.metrics.clone()), None => { - dbg!("⚠️ metric error: No App State"); + debug!("⚠️ metric error: No App State"); None } }, @@ -45,7 +46,7 @@ impl Metrics { match self.client.unwrap().incr(label) { Err(e) => { // eat the metric, but log the error - dbg!("⚠️ Metric {} error: {:?} ", label, e); + debug!("⚠️ Metric {} error: {:?} ", label, e); } Ok(_v) => { // v.as_metric_str() @@ -79,7 +80,7 @@ pub fn metrics_from_opts(opts: &Settings) -> Result { }; Ok(builder .with_error_handler(|err| { - dbg!("⚠️ Metric send error:", err); + debug!("⚠️ Metric send error: {:?}", err); }) .build()) } diff --git a/src/settings.rs b/src/settings.rs index d0d708c7..b8e458a9 100644 --- a/src/settings.rs +++ b/src/settings.rs @@ -1,6 +1,7 @@ //! Application settings objects and initialization use config::{Config, ConfigError, Environment, File}; +use log::debug; use serde::{de::Deserializer, Deserialize, Serialize}; use url::Url; @@ -118,11 +119,11 @@ impl Settings { "For example to set `database_url` use env var `{}_DATABASE_URL`\n", PREFIX.to_uppercase() ); - dbg!("⚠️ Configuration error: Value undefined", &v); + debug!("⚠️ Configuration error: Value undefined {:?}", &v); return Err(ConfigError::NotFound(v)); } _ => { - dbg!("⚠️ Other: ", &e); + debug!("⚠️ Other: {:?}", &e); return Err(e); } }, diff --git a/src/web/extractors.rs b/src/web/extractors.rs index 58ba3068..3436048e 100644 --- a/src/web/extractors.rs +++ b/src/web/extractors.rs @@ -16,6 +16,7 @@ use actix_web::{ }; use futures::{future, Future}; use lazy_static::lazy_static; +use log::debug; use regex::Regex; use serde::{ de::{Deserializer, Error as SerdeError, IgnoredAny}, @@ -120,7 +121,7 @@ impl FromRequest for BsoBodies { let default = HeaderValue::from_static(""); let content_type = get_trimmed_header(headers, CONTENT_TYPE, &default); - dbg!(&content_type); + debug!("content_type: {:?}", &content_type); match content_type.as_str() { "application/json" | "text/plain" | "application/newlines" | "" => (), @@ -138,7 +139,7 @@ impl FromRequest for BsoBodies { // Load the entire request into a String let fut = ::from_request(req, payload).map_err(|e| { - dbg!("⚠️ Payload read error", e); + debug!("⚠️ Payload read error: {:?}", e); ValidationErrorKind::FromDetails( "Mimetype/encoding/content-length error".to_owned(), RequestErrorLocation::Header, @@ -165,7 +166,7 @@ impl FromRequest for BsoBodies { let state = match req.app_data::() { Some(s) => s, None => { - dbg!("⚠️ Could not load the app state"); + debug!("⚠️ Could not load the app state"); return Box::new(future::err( ValidationErrorKind::FromDetails( "Internal error".to_owned(), @@ -315,7 +316,7 @@ impl FromRequest for BsoBody { let state = match req.app_data::() { Some(s) => s, None => { - dbg!("⚠️ Could not load the app state"); + debug!("⚠️ Could not load the app state"); return Box::new(future::err( ValidationErrorKind::FromDetails( "Internal error".to_owned(), @@ -391,7 +392,7 @@ impl BsoParam { } if let Some(v) = elements.get(5) { let sv = String::from_str(v).map_err(|e| { - dbg!("⚠️ BsoParam Error", v, e); + debug!("⚠️ BsoParam Error element:{:?} error:{:?}", v, e); ValidationErrorKind::FromDetails( "Invalid BSO".to_owned(), RequestErrorLocation::Path, @@ -615,7 +616,7 @@ impl FromRequest for CollectionPostRequest { let state = match req.app_data::() { Some(s) => s, None => { - dbg!("⚠️ Could not load the app state"); + debug!("⚠️ Could not load the app state"); return Box::new(future::err( ValidationErrorKind::FromDetails( "Internal error".to_owned(), @@ -798,7 +799,7 @@ impl FromRequest for ConfigRequest { let state = match req.app_data::() { Some(s) => s, None => { - dbg!("⚠️ Could not load the app state"); + debug!("⚠️ Could not load the app state"); return Err(ValidationErrorKind::FromDetails( "Internal error".to_owned(), RequestErrorLocation::Unknown, @@ -859,7 +860,7 @@ impl HawkIdentifier { let elements: Vec<&str> = uri.path().split('/').collect(); if let Some(v) = elements.get(2) { u64::from_str(v).map_err(|e| { - dbg!("⚠️ HawkIdentifier Error", v, e); + debug!("⚠️ HawkIdentifier Error {:?} {:?}", v, e); ValidationErrorKind::FromDetails( "Invalid UID".to_owned(), RequestErrorLocation::Path, @@ -936,7 +937,7 @@ impl FromRequest for HawkIdentifier { let state = match req.app_data::() { Some(s) => s, None => { - dbg!("⚠️ Could not load the app state"); + debug!("⚠️ Could not load the app state"); return Err(ValidationErrorKind::FromDetails( "Internal error".to_owned(), RequestErrorLocation::Unknown, @@ -964,7 +965,7 @@ impl From for HawkIdentifier { pub fn extrude_db(exts: &Extensions) -> Result, Error> { exts.get::>().cloned().ok_or_else(|| { - dbg!("⚠️ DB Error: No db"); + debug!("⚠️ DB Error: No db"); ErrorInternalServerError("Unexpected Db error: No DB".to_owned()) }) } @@ -1074,7 +1075,7 @@ impl FromRequest for BatchRequestOpt { let state = match req.app_data::() { Some(s) => s, None => { - dbg!("⚠️ Could not load the app state"); + debug!("⚠️ Could not load the app state"); return Err(ValidationErrorKind::FromDetails( "Internal error".to_owned(), RequestErrorLocation::Unknown, diff --git a/src/web/middleware.rs b/src/web/middleware.rs index 081ff345..02d3c115 100644 --- a/src/web/middleware.rs +++ b/src/web/middleware.rs @@ -18,6 +18,7 @@ use futures::{ future::{self, Either, FutureResult}, Future, Poll, }; +use log::debug; use crate::db::{params, util::SyncTimestamp}; use crate::error::{ApiError, ApiErrorKind}; @@ -200,7 +201,7 @@ where Err(e) => { // Semi-example to show how to use metrics inside of middleware. metrics::Metrics::from(&state).incr("sync.error.collectionParam"); - dbg!("⚠️ CollectionParam err: {:?}", e); + debug!("⚠️ CollectionParam err: {:?}", e); return Box::new(future::ok( sreq.into_response( HttpResponse::InternalServerError() @@ -215,7 +216,7 @@ where let hawk_user_id = match sreq.get_hawk_id() { Ok(v) => v, Err(e) => { - dbg!("⚠️ Bad Hawk Id: ", e); + debug!("⚠️ Bad Hawk Id: {:?}", e); return Box::new(future::ok( sreq.into_response( HttpResponse::Unauthorized() @@ -331,7 +332,7 @@ where None => PreConditionHeader::NoHeader, }, Err(e) => { - dbg!("⚠️ Precondition error", e); + debug!("⚠️ Precondition error {:?}", e); return Box::new(future::ok( sreq.into_response( HttpResponse::BadRequest() @@ -345,7 +346,7 @@ where let user_id = match sreq.get_hawk_id() { Ok(v) => v, Err(e) => { - dbg!("⚠️ Hawk header error", e); + debug!("⚠️ Hawk header error {:?}", e); return Box::new(future::ok( sreq.into_response( HttpResponse::Unauthorized() @@ -360,7 +361,7 @@ where let db = match edb { Ok(v) => v, Err(e) => { - dbg!("⚠️ Database access error", e); + debug!("⚠️ Database access error {:?}", e); return Box::new(future::ok( sreq.into_response( HttpResponse::InternalServerError() @@ -376,7 +377,7 @@ where let collection = match col_result { Ok(v) => v.map(|c| c.collection), Err(e) => { - dbg!("⚠️ Collection Error: ", e); + debug!("⚠️ Collection Error: {:?}", e); return Box::new(future::ok( sreq.into_response( HttpResponse::InternalServerError() @@ -431,7 +432,7 @@ where if let Ok(ts_header) = header::HeaderValue::from_str(&resource_ts.as_header()) { - dbg!(format!("📝 Setting X-Last-Modfied {:?}", ts_header)); + debug!("📝 Setting X-Last-Modfied {:?}", ts_header); resp.headers_mut().insert( header::HeaderName::from_static(X_LAST_MODIFIED), ts_header,