diff --git a/Cargo.lock b/Cargo.lock index 682dd6c..076c115 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -108,7 +108,7 @@ dependencies = [ "serde_urlencoded", "sha-1", "slab", - "time", + "time 0.2.16", ] [[package]] @@ -299,7 +299,7 @@ dependencies = [ "serde_json", "serde_urlencoded", "socket2", - "time", + "time 0.2.16", "tinyvec", "url", ] @@ -553,6 +553,17 @@ version = "0.1.10" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4785bdd1c96b2a846b2bd7cc02e86b6b3dbf14e7e53446c4f54c92a361040822" +[[package]] +name = "chrono" +version = "0.4.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "80094f509cf8b5ae86a4966a39b3ff66cd7e2a3e594accec3743ff3fabeab5b2" +dependencies = [ + "num-integer", + "num-traits", + "time 0.1.43", +] + [[package]] name = "clap" version = "2.33.1" @@ -724,19 +735,6 @@ dependencies = [ "syn", ] -[[package]] -name = "env_logger" -version = "0.7.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" -dependencies = [ - "atty", - "humantime", - "log", - "regex", - "termcolor", -] - [[package]] name = "fake-simd" version = "0.1.2" @@ -1002,15 +1000,6 @@ version = "1.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cd179ae861f0c2e53da70d892f5f3029f9594be0c41dc5269cd371691b1dc2f9" -[[package]] -name = "humantime" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" -dependencies = [ - "quick-error", -] - [[package]] name = "idna" version = "0.2.0" @@ -1177,6 +1166,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.8" @@ -1381,11 +1379,9 @@ dependencies = [ "actix-web", "anyhow", "bytes", - "env_logger", "futures", "gif", "image", - "log", "mime", "rand", "serde", @@ -1394,6 +1390,9 @@ dependencies = [ "sled", "structopt", "thiserror", + "tracing", + "tracing-futures", + "tracing-subscriber", ] [[package]] @@ -1591,6 +1590,16 @@ dependencies = [ "thread_local", ] +[[package]] +name = "regex-automata" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4" +dependencies = [ + "byteorder", + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.18" @@ -1766,6 +1775,15 @@ dependencies = [ "opaque-debug", ] +[[package]] +name = "sharded-slab" +version = "0.0.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "06d5a3f5166fb5b42a5439f2eee8b9de149e235961e3eb21c5808fc3ea17ff3e" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook-registry" version = "1.2.0" @@ -1933,15 +1951,6 @@ dependencies = [ "syn", ] -[[package]] -name = "termcolor" -version = "1.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "bb6bfa289a4d7c5766392812c0a1f4c1ba45afa1ad47803c11e1f407d846d75f" -dependencies = [ - "winapi-util", -] - [[package]] name = "textwrap" version = "0.11.0" @@ -2000,6 +2009,16 @@ dependencies = [ "miniz_oxide", ] +[[package]] +name = "time" +version = "0.1.43" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ca8a50ef2360fbd1eeb0ecd46795a87a19024eb4b53c5dc916ca1fd95fe62438" +dependencies = [ + "libc", + "winapi 0.3.8", +] + [[package]] name = "time" version = "0.2.16" @@ -2105,6 +2124,88 @@ dependencies = [ "tokio", ] +[[package]] +name = "tracing" +version = "0.1.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a41f40ed0e162c911ac6fcb53ecdc8134c46905fdbbae8c50add462a538b495f" +dependencies = [ + "cfg-if", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "99bbad0de3fd923c9c3232ead88510b783e5a4d16a6154adffa3d53308de984c" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0aa83a9a47081cd522c09c81b31aec2c9273424976f922ad61c053b58350b715" +dependencies = [ + "lazy_static", +] + +[[package]] +name = "tracing-futures" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ab7bb6f14721aa00656086e9335d363c5c8747bae02ebe32ea2c7dece5689b4c" +dependencies = [ + "pin-project", + "tracing", +] + +[[package]] +name = "tracing-log" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5e0f8c7178e13481ff6765bd169b33e8d554c5d2bbede5e32c356194be02b9b9" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b6ccba2f8f16e0ed268fc765d9b7ff22e965e7185d32f8f1ec8294fe17d86e79" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1d53c40489aa69c9aed21ff483f26886ca8403df33bdc2d2f87c60c1617826d2" +dependencies = [ + "ansi_term", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec", + "tracing-core", + "tracing-log", + "tracing-serde", +] + [[package]] name = "trust-dns-proto" version = "0.19.5" @@ -2355,15 +2456,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" -[[package]] -name = "winapi-util" -version = "0.1.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" -dependencies = [ - "winapi 0.3.8", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index 4df1a68..5881019 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -17,11 +17,9 @@ actix-rt = "1.1.1" actix-web = { version = "3.0.0-alpha.2", features = ["rustls"] } anyhow = "1.0" bytes = "0.5" -env_logger = "0.7" futures = "0.3.4" gif = "0.10.3" image = "0.23.4" -log = "0.4" mime = "0.3.1" rand = "0.7.3" serde = { version = "1.0", features = ["derive"] } @@ -30,3 +28,6 @@ sha2 = "0.9.0" sled = "0.32.0-rc1" structopt = "0.3.14" thiserror = "1.0" +tracing = "0.1.15" +tracing-futures = "0.2.4" +tracing-subscriber = { version = "0.2.5", features = ["fmt", "tracing-log"] } diff --git a/src/main.rs b/src/main.rs index ef87ac1..48a35f5 100644 --- a/src/main.rs +++ b/src/main.rs @@ -7,17 +7,24 @@ use actix_web::{ web, App, HttpResponse, HttpServer, }; use futures::stream::{Stream, TryStreamExt}; -use log::{error, info}; use std::{collections::HashSet, path::PathBuf}; use structopt::StructOpt; +use tracing::{debug, error, info, instrument}; +use tracing_subscriber::EnvFilter; mod config; mod error; +mod middleware; mod processor; mod upload_manager; mod validate; -use self::{config::Config, error::UploadError, upload_manager::UploadManager}; +use self::{ + config::Config, + error::UploadError, + middleware::Tracing, + upload_manager::{UploadManager, UploadStream}, +}; const MEGABYTES: usize = 1024 * 1024; const HOURS: u32 = 60 * 60; @@ -26,10 +33,12 @@ const HOURS: u32 = 60 * 60; async fn safe_save_file(path: PathBuf, bytes: bytes::Bytes) -> Result<(), UploadError> { if let Some(path) = path.parent() { // create the directory for the file + debug!("Creating directory"); actix_fs::create_dir_all(path.to_owned()).await?; } // Only write the file if it doesn't already exist + debug!("Checking if file already exists"); if let Err(e) = actix_fs::metadata(path.clone()).await { if e.kind() != Some(std::io::ErrorKind::NotFound) { return Err(e.into()); @@ -39,15 +48,18 @@ async fn safe_save_file(path: PathBuf, bytes: bytes::Bytes) -> Result<(), Upload } // Open the file for writing + debug!("Creating file"); let file = actix_fs::file::create(path.clone()).await?; // try writing + debug!("Writing to file"); if let Err(e) = actix_fs::file::write(file, bytes).await { error!("Error writing file, {}", e); // remove file if writing failed before completion actix_fs::remove_file(path).await?; return Err(e.into()); } + debug!("File written"); Ok(()) } @@ -74,6 +86,7 @@ fn from_ext(ext: std::ffi::OsString) -> mime::Mime { } /// Handle responding to succesful uploads +#[instrument] async fn upload( value: Value, manager: web::Data, @@ -123,7 +136,7 @@ async fn download( let stream = Box::pin(futures::stream::once(fut)); - let alias = manager.upload(stream).await?; + let alias = manager.upload(UploadStream::new(stream)).await?; let delete_token = manager.delete_token(alias.clone()).await?; Ok(HttpResponse::Created().json(serde_json::json!({ @@ -147,6 +160,7 @@ async fn delete( } /// Serve files +#[instrument] async fn serve( segments: web::Path, manager: web::Data, @@ -159,7 +173,9 @@ async fn serve( .collect(); let alias = segments.pop().ok_or(UploadError::MissingFilename)?; + debug!("Building chain"); let chain = self::processor::build_chain(&segments, whitelist.as_ref().as_ref()); + debug!("Chain built"); let name = manager.from_alias(alias).await?; let base = manager.image_dir(); @@ -184,23 +200,32 @@ async fn serve( // Read the image file & produce a DynamicImage // // Drop bytes so we don't keep it around in memory longer than we need to + debug!("Reading image"); let (img, format) = { let bytes = actix_fs::read(original_path.clone()).await?; - let format = image::guess_format(&bytes)?; + let bytes2 = bytes.clone(); + let format = web::block(move || image::guess_format(&bytes2)).await?; let img = web::block(move || image::load_from_memory(&bytes)).await?; (img, format) }; + debug!("Image read"); - let img = self::processor::process_image(chain, img).await?; + debug!("Processing image"); + let img = self::processor::process_image(chain, img.into()) + .await? + .inner; + debug!("Image processed"); // perform thumbnail operation in a blocking thread + debug!("Exporting image"); let img_bytes: bytes::Bytes = web::block(move || { let mut bytes = std::io::Cursor::new(vec![]); img.write_to(&mut bytes, format)?; Ok(bytes::Bytes::from(bytes.into_inner())) as Result<_, image::error::ImageError> }) .await?; + debug!("Image exported"); let path2 = path.clone(); let img_bytes2 = img_bytes.clone(); @@ -254,8 +279,15 @@ struct UrlQuery { #[actix_rt::main] async fn main() -> Result<(), anyhow::Error> { let config = Config::from_args(); - std::env::set_var("RUST_LOG", "info"); - env_logger::init(); + + if std::env::var("RUST_LOG").is_err() { + std::env::set_var("RUST_LOG", "info"); + } + + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::from_default_env()) + .init(); + let manager = UploadManager::new(config.data_dir(), config.format()).await?; // Create a new Multipart Form validator @@ -272,7 +304,7 @@ async fn main() -> Result<(), anyhow::Error> { let manager = manager2.clone(); async move { - manager.upload(stream).await.map(|alias| { + manager.upload(stream.into()).await.map(|alias| { let mut path = PathBuf::new(); path.push(alias); Some(path) @@ -297,7 +329,7 @@ async fn main() -> Result<(), anyhow::Error> { async move { manager - .import(filename, content_type, validate_imports, stream) + .import(filename, content_type, validate_imports, stream.into()) .await .map(|alias| { let mut path = PathBuf::new(); @@ -317,8 +349,9 @@ async fn main() -> Result<(), anyhow::Error> { let config = config2.clone(); App::new() - .wrap(Logger::default()) .wrap(Compress::default()) + .wrap(Logger::default()) + .wrap(Tracing) .data(manager.clone()) .data(client) .data(config.filter_whitelist()) diff --git a/src/middleware.rs b/src/middleware.rs new file mode 100644 index 0000000..7b5bedb --- /dev/null +++ b/src/middleware.rs @@ -0,0 +1,48 @@ +use actix_web::dev::{Service, Transform}; +use futures::future::{ok, Ready}; +use std::task::{Context, Poll}; +use tracing_futures::{Instrument, Instrumented}; + +pub(crate) struct Tracing; + +pub(crate) struct TracingMiddleware { + inner: S, +} + +impl Transform for Tracing +where + S: Service, + S::Future: 'static, +{ + type Request = S::Request; + type Response = S::Response; + type Error = S::Error; + type InitError = (); + type Transform = TracingMiddleware; + type Future = Ready>; + + fn new_transform(&self, service: S) -> Self::Future { + ok(TracingMiddleware { inner: service }) + } +} + +impl Service for TracingMiddleware +where + S: Service, + S::Future: 'static, +{ + type Request = S::Request; + type Response = S::Response; + type Error = S::Error; + type Future = Instrumented; + + fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll> { + self.inner.poll_ready(cx) + } + + fn call(&mut self, req: S::Request) -> Self::Future { + self.inner + .call(req) + .instrument(tracing::info_span!("request")) + } +} diff --git a/src/processor.rs b/src/processor.rs index d94b64c..d93b2a1 100644 --- a/src/processor.rs +++ b/src/processor.rs @@ -1,8 +1,8 @@ use crate::error::UploadError; use actix_web::web; use image::{DynamicImage, GenericImageView}; -use log::debug; use std::{collections::HashSet, path::PathBuf}; +use tracing::{debug, instrument}; pub(crate) trait Processor { fn name() -> &'static str @@ -141,11 +141,40 @@ macro_rules! parse { }}; } -pub(crate) fn build_chain( - args: &[String], - whitelist: Option<&HashSet>, -) -> Vec> { - args.into_iter() +pub(crate) struct ProcessChain { + inner: Vec>, +} + +impl std::fmt::Debug for ProcessChain { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + f.debug_struct("ProcessChain") + .field("inner", &format!("{} operations", self.inner.len())) + .finish() + } +} + +pub(crate) struct ImageWrapper { + pub(crate) inner: DynamicImage, +} + +impl From for ImageWrapper { + fn from(inner: DynamicImage) -> Self { + ImageWrapper { inner } + } +} + +impl std::fmt::Debug for ImageWrapper { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + f.debug_struct("ImageWrapper") + .field("inner", &"DynamicImage".to_string()) + .finish() + } +} + +#[instrument] +pub(crate) fn build_chain(args: &[String], whitelist: Option<&HashSet>) -> ProcessChain { + let inner = args + .into_iter() .filter_map(|arg| { parse!(Identity, arg.as_str(), whitelist); parse!(Thumbnail, arg.as_str(), whitelist); @@ -155,27 +184,30 @@ pub(crate) fn build_chain( None }) - .collect() + .collect(); + + ProcessChain { inner } } -pub(crate) fn build_path( - base: PathBuf, - args: &[Box], - filename: String, -) -> PathBuf { - let mut path = args.iter().fold(base, |acc, processor| processor.path(acc)); +pub(crate) fn build_path(base: PathBuf, chain: &ProcessChain, filename: String) -> PathBuf { + let mut path = chain + .inner + .iter() + .fold(base, |acc, processor| processor.path(acc)); path.push(filename); path } +#[instrument] pub(crate) async fn process_image( - args: Vec>, - mut img: DynamicImage, -) -> Result { - for processor in args.into_iter() { - img = web::block(move || processor.process(img)).await?; + chain: ProcessChain, + img: ImageWrapper, +) -> Result { + let mut inner = img.inner; + for processor in chain.inner.into_iter() { + inner = web::block(move || processor.process(inner)).await?; } - Ok(img) + Ok(inner.into()) } diff --git a/src/upload_manager.rs b/src/upload_manager.rs index 68b0663..0bc7c30 100644 --- a/src/upload_manager.rs +++ b/src/upload_manager.rs @@ -1,9 +1,9 @@ use crate::{config::Format, error::UploadError, safe_save_file, to_ext, validate::validate_image}; use actix_web::web; use futures::stream::{Stream, StreamExt}; -use log::{error, warn}; use sha2::Digest; use std::{path::PathBuf, pin::Pin, sync::Arc}; +use tracing::{debug, error, instrument, warn}; #[derive(Clone)] pub struct UploadManager { @@ -19,7 +19,39 @@ struct UploadManagerInner { db: sled::Db, } -type UploadStream = Pin>>>; +impl std::fmt::Debug for UploadManager { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + f.debug_struct("UploadManager") + .field("inner", &format!("Arc")) + .finish() + } +} + +type StreamAlias = Pin>>>; + +pub(crate) struct UploadStream { + inner: StreamAlias, +} + +impl UploadStream { + pub(crate) fn new(s: StreamAlias) -> Self { + UploadStream { inner: s } + } +} + +impl From> for UploadStream { + fn from(s: StreamAlias) -> Self { + UploadStream { inner: s } + } +} + +impl std::fmt::Debug for UploadStream { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + f.debug_struct("UploadStream") + .field("inner", &"stream".to_string()) + .finish() + } +} enum Dup { Exists, @@ -162,12 +194,16 @@ impl UploadManager { } /// Generate a delete token for an alias + #[instrument] pub(crate) async fn delete_token(&self, alias: String) -> Result { + debug!("Generating delete token"); use rand::distributions::{Alphanumeric, Distribution}; let rng = rand::thread_rng(); let s: String = Alphanumeric.sample_iter(rng).take(10).collect(); let delete_token = s.clone(); + debug!("Generated delete token"); + debug!("Saving delete token"); let alias_tree = self.inner.alias_tree.clone(); let key = delete_key(&alias); let res = web::block(move || { @@ -178,6 +214,7 @@ impl UploadManager { ) }) .await?; + debug!("Delete token saved"); if let Err(sled::CompareAndSwapError { current: Some(ivec), @@ -226,25 +263,36 @@ impl UploadManager { } /// Upload the file, discarding bytes if it's already present, or saving if it's new + #[instrument] pub(crate) async fn upload(&self, stream: UploadStream) -> Result where UploadError: From, { // -- READ IN BYTES FROM CLIENT -- + debug!("Reading stream"); let bytes = read_stream(stream).await?; + debug!("Read stream"); // -- VALIDATE IMAGE -- + debug!("Validating image"); let format = self.inner.format.clone(); let (bytes, content_type) = validate_image(bytes, format).await?; + debug!("Image validated"); // -- DUPLICATE CHECKS -- // Cloning bytes is fine because it's actually a pointer + debug!("Hashing bytes"); let hash = self.hash(bytes.clone()).await?; + debug!("Bytes hashed"); + debug!("Adding alias"); let alias = self.add_alias(&hash, content_type.clone()).await?; + debug!("Alias added"); + debug!("Saving file"); self.save_upload(bytes, hash, content_type).await?; + debug!("File saved"); // Return alias to file Ok(alias) @@ -346,6 +394,7 @@ impl UploadManager { } // check for an already-uploaded image with this hash, returning the path to the target file + #[instrument] async fn check_duplicate( &self, hash: Vec, @@ -382,6 +431,7 @@ impl UploadManager { } // generate a short filename that isn't already in-use + #[instrument] async fn next_file(&self, content_type: mime::Mime) -> Result { let image_dir = self.image_dir(); use rand::distributions::{Alphanumeric, Distribution}; @@ -417,6 +467,7 @@ impl UploadManager { // Add an alias to an existing file // // This will help if multiple 'users' upload the same file, and one of them wants to delete it + #[instrument] async fn add_alias( &self, hash: &[u8], @@ -432,6 +483,7 @@ impl UploadManager { // Add a pre-defined alias to an existin file // // DANGER: this can cause BAD BAD BAD conflicts if the same alias is used for multiple files + #[instrument] async fn store_alias(&self, hash: &[u8], alias: &str) -> Result<(), UploadError> { let alias = alias.to_string(); loop { @@ -504,10 +556,12 @@ impl UploadManager { } } -async fn read_stream(mut stream: UploadStream) -> Result +#[instrument] +async fn read_stream(stream: UploadStream) -> Result where UploadError: From, { + let mut stream = stream.inner; let mut bytes = bytes::BytesMut::new(); while let Some(res) = stream.next().await { diff --git a/src/validate.rs b/src/validate.rs index 4108e50..efa6810 100644 --- a/src/validate.rs +++ b/src/validate.rs @@ -3,6 +3,7 @@ use actix_web::web; use bytes::Bytes; use image::{ImageDecoder, ImageEncoder, ImageFormat}; use std::io::Cursor; +use tracing::debug; #[derive(Debug, thiserror::Error)] pub(crate) enum GifError { @@ -31,13 +32,16 @@ pub(crate) async fn validate_image( let format = image::guess_format(&bytes).map_err(UploadError::InvalidImage)?; - match format { + debug!("Validating {:?}", format); + let res = match format { ImageFormat::Png => Ok((validate_png(bytes)?, mime::IMAGE_PNG)), ImageFormat::Jpeg => Ok((validate_jpg(bytes)?, mime::IMAGE_JPEG)), ImageFormat::Bmp => Ok((validate_bmp(bytes)?, mime::IMAGE_BMP)), ImageFormat::Gif => Ok((validate_gif(bytes)?, mime::IMAGE_GIF)), _ => Err(UploadError::UnsupportedFormat), - } + }; + debug!("Validated"); + res }) .await?;