From 8d1b72b9512b90775e671b7ba08cd552a0aabd13 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa?= Date: Fri, 6 Dec 2019 22:19:07 +0100 Subject: [PATCH] Collapsed log messages from 3 lines per request to 2 and hidden the ones valued as less informative. Use LOG_LEVEL debug or trace to recover them. Removed LOG_MOUNTS and bundled it with LOG_LEVEL debug and trace. Removed duplicate error messages Made websocket not proxied message more prominent, but only print it once. --- .env.template | 9 ++---- src/api/notifications.rs | 19 ++++++++--- src/api/web.rs | 2 ++ src/config.rs | 3 -- src/error.rs | 14 ++++---- src/main.rs | 67 +++++++++++++++++++++----------------- src/util.rs | 69 +++++++++++++++++++++++++++++++++++++--- 7 files changed, 130 insertions(+), 53 deletions(-) diff --git a/.env.template b/.env.template index 3ccdbdbd..5b2fe2ce 100644 --- a/.env.template +++ b/.env.template @@ -37,14 +37,10 @@ # WEBSOCKET_ADDRESS=0.0.0.0 # WEBSOCKET_PORT=3012 -## Enable extended logging -## This shows timestamps and allows logging to file and to syslog -### To enable logging to file, use the LOG_FILE env variable -### To enable syslog, use the USE_SYSLOG env variable +## Enable extended logging, which shows timestamps and targets in the logs # EXTENDED_LOGGING=true ## Logging to file -## This requires extended logging ## It's recommended to also set 'ROCKET_CLI_COLORS=off' # LOG_FILE=/path/to/log @@ -56,7 +52,8 @@ ## Log level ## Change the verbosity of the log output ## Valid values are "trace", "debug", "info", "warn", "error" and "off" -## This requires extended logging +## Setting it to "trace" or "debug" would also show logs for mounted +## routes and static file, websocket and alive requests # LOG_LEVEL=Info ## Enable WAL for the DB diff --git a/src/api/notifications.rs b/src/api/notifications.rs index ee7acd82..4781aa2d 100644 --- a/src/api/notifications.rs +++ b/src/api/notifications.rs @@ -1,20 +1,31 @@ +use std::sync::atomic::{AtomicBool, Ordering}; + use rocket::Route; use rocket_contrib::json::Json; use serde_json::Value as JsonValue; -use crate::api::JsonResult; +use crate::api::{EmptyResult, JsonResult}; use crate::auth::Headers; use crate::db::DbConn; -use crate::CONFIG; +use crate::{Error, CONFIG}; pub fn routes() -> Vec { routes![negotiate, websockets_err] } +static SHOW_WEBSOCKETS_MSG: AtomicBool = AtomicBool::new(true); + #[get("/hub")] -fn websockets_err() -> JsonResult { - err!("'/notifications/hub' should be proxied to the websocket server or notifications won't work. Go to the README for more info.") +fn websockets_err() -> EmptyResult { + if CONFIG.websocket_enabled() && SHOW_WEBSOCKETS_MSG.compare_and_swap(true, false, Ordering::Relaxed) { + err!("########################################################### + '/notifications/hub' should be proxied to the websocket server or notifications won't work. + Go to the Wiki for more info, or disable WebSockets setting WEBSOCKET_ENABLED=false. + ###########################################################################################") + } else { + Err(Error::empty()) + } } #[post("/hub/negotiate")] diff --git a/src/api/web.rs b/src/api/web.rs index 24847b9e..72c89b5b 100644 --- a/src/api/web.rs +++ b/src/api/web.rs @@ -12,6 +12,8 @@ use crate::error::Error; use crate::CONFIG; pub fn routes() -> Vec { + // If addding more routes here, consider also adding them to + // crate::utils::LOGGED_ROUTES to make sure they appear in the log if CONFIG.web_vault_enabled() { routes![web_index, app_id, web_files, attachments, alive, static_files] } else { diff --git a/src/config.rs b/src/config.rs index bf57400a..88869f71 100644 --- a/src/config.rs +++ b/src/config.rs @@ -294,9 +294,6 @@ make_config! { /// Reload templates (Dev) |> When this is set to true, the templates get reloaded with every request. /// ONLY use this during development, as it can slow down the server reload_templates: bool, true, def, false; - - /// Log routes at launch (Dev) - log_mounts: bool, true, def, false; /// Enable extended logging extended_logging: bool, false, def, true; /// Enable the log to output to Syslog diff --git a/src/error.rs b/src/error.rs index 5f99db4e..47be6740 100644 --- a/src/error.rs +++ b/src/error.rs @@ -86,7 +86,7 @@ impl std::fmt::Debug for Error { fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { match self.source() { Some(e) => write!(f, "{}.\n[CAUSE] {:#?}", self.message, e), - None => write!(f, "{}. {}", self.message, self.error), + None => write!(f, "{}", self.message), } } } @@ -170,15 +170,17 @@ use rocket::response::{self, Responder, Response}; impl<'r> Responder<'r> for Error { fn respond_to(self, _: &Request) -> response::Result<'r> { - let usr_msg = format!("{}", self); - error!("{:#?}", self); + match self.error { + ErrorKind::EmptyError(_) => {} // Don't print the error in this situation + _ => error!(target: "error", "{:#?}", self), + }; let code = Status::from_code(self.error_code).unwrap_or(Status::BadRequest); Response::build() .status(code) .header(ContentType::JSON) - .sized_body(Cursor::new(usr_msg)) + .sized_body(Cursor::new(format!("{}", self))) .ok() } } @@ -206,11 +208,11 @@ macro_rules! err_json { #[macro_export] macro_rules! err_handler { ($expr:expr) => {{ - error!("Unauthorized Error: {}", $expr); + error!(target: "auth", "Unauthorized Error: {}", $expr); return rocket::Outcome::Failure((rocket::http::Status::Unauthorized, $expr)); }}; ($usr_msg:expr, $log_value:expr) => {{ - error!("Unauthorized Error: {}. {}", $usr_msg, $log_value); + error!(target: "auth", "Unauthorized Error: {}. {}", $usr_msg, $log_value); return rocket::Outcome::Failure((rocket::http::Status::Unauthorized, $usr_msg)); }}; } diff --git a/src/main.rs b/src/main.rs index 862b53b1..52a27604 100644 --- a/src/main.rs +++ b/src/main.rs @@ -23,9 +23,10 @@ extern crate derive_more; extern crate num_derive; use std::{ + fs::create_dir_all, path::Path, process::{exit, Command}, - fs::create_dir_all, + str::FromStr, }; #[macro_use] @@ -44,9 +45,14 @@ pub use error::{Error, MapResult}; fn main() { launch_info(); - if CONFIG.extended_logging() { - init_logging().ok(); - } + use log::LevelFilter as LF; + let level = LF::from_str(&CONFIG.log_level()).expect("Valid log level"); + init_logging(level).ok(); + + let extra_debug = match level { + LF::Trace | LF::Debug => true, + _ => false, + }; check_db(); check_rsa_keys(); @@ -55,7 +61,7 @@ fn main() { create_icon_cache_folder(); - launch_rocket(); + launch_rocket(extra_debug); } fn launch_info() { @@ -73,10 +79,23 @@ fn launch_info() { println!("\\--------------------------------------------------------------------/\n"); } -fn init_logging() -> Result<(), fern::InitError> { - use std::str::FromStr; +fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { let mut logger = fern::Dispatch::new() - .format(|out, message, record| { + .level(level) + // Hide unknown certificate errors if using self-signed + .level_for("rustls::session", log::LevelFilter::Off) + // Hide failed to close stream messages + .level_for("hyper::server", log::LevelFilter::Warn) + // Silence rocket logs + .level_for("_", log::LevelFilter::Off) + .level_for("launch", log::LevelFilter::Off) + .level_for("launch_", log::LevelFilter::Off) + .level_for("rocket::rocket", log::LevelFilter::Off) + .level_for("rocket::fairing", log::LevelFilter::Off) + .chain(std::io::stdout()); + + if CONFIG.extended_logging() { + logger = logger.format(|out, message, record| { out.finish(format_args!( "{}[{}][{}] {}", chrono::Local::now().format("[%Y-%m-%d %H:%M:%S]"), @@ -84,13 +103,10 @@ fn init_logging() -> Result<(), fern::InitError> { record.level(), message )) - }) - .level(log::LevelFilter::from_str(&CONFIG.log_level()).expect("Valid log level")) - // Hide unknown certificate errors if using self-signed - .level_for("rustls::session", log::LevelFilter::Off) - // Hide failed to close stream messages - .level_for("hyper::server", log::LevelFilter::Warn) - .chain(std::io::stdout()); + }); + } else { + logger = logger.format(|out, message, _| out.finish(format_args!("{}", message))); + } if let Some(log_file) = CONFIG.log_file() { logger = logger.chain(fern::log_file(log_file)?); @@ -236,33 +252,24 @@ mod migrations { } } -fn launch_rocket() { +fn launch_rocket(extra_debug: bool) { // Create Rocket object, this stores current log level and sets it's own let rocket = rocket::ignite(); - // If we aren't logging the mounts, we force the logging level down - if !CONFIG.log_mounts() { - log::set_max_level(log::LevelFilter::Warn); - } - + // If addding more base paths here, consider also adding them to + // crate::utils::LOGGED_ROUTES to make sure they appear in the log let rocket = rocket .mount("/", api::web_routes()) .mount("/api", api::core_routes()) .mount("/admin", api::admin_routes()) .mount("/identity", api::identity_routes()) .mount("/icons", api::icons_routes()) - .mount("/notifications", api::notifications_routes()); - - // Force the level up for the fairings, managed state and lauch - if !CONFIG.log_mounts() { - log::set_max_level(log::LevelFilter::max()); - } - - let rocket = rocket + .mount("/notifications", api::notifications_routes()) .manage(db::init_pool()) .manage(api::start_notification_server()) .attach(util::AppHeaders()) - .attach(util::CORS()); + .attach(util::CORS()) + .attach(util::BetterLogging(extra_debug)); // Launch and print error if there is one // The launch will restore the original logging level diff --git a/src/util.rs b/src/util.rs index 39ee1f99..1dde702b 100644 --- a/src/util.rs +++ b/src/util.rs @@ -2,9 +2,9 @@ // Web Headers and caching // use rocket::fairing::{Fairing, Info, Kind}; +use rocket::http::{ContentType, Header, HeaderMap, Method, Status}; use rocket::response::{self, Responder}; -use rocket::{Request, Response}; -use rocket::http::{Header, HeaderMap, ContentType, Method, Status}; +use rocket::{Data, Request, Response, Rocket}; use std::io::Cursor; pub struct AppHeaders(); @@ -55,7 +55,7 @@ impl Fairing for CORS { fn info(&self) -> Info { Info { name: "CORS", - kind: Kind::Response + kind: Kind::Response, } } @@ -69,7 +69,7 @@ impl Fairing for CORS { if request.method() == Method::Options { let req_allow_headers = CORS::get_header(&req_headers, "Access-Control-Request-Headers"); - let req_allow_method = CORS::get_header(&req_headers,"Access-Control-Request-Method"); + let req_allow_method = CORS::get_header(&req_headers, "Access-Control-Request-Method"); response.set_header(Header::new("Access-Control-Allow-Methods", req_allow_method)); response.set_header(Header::new("Access-Control-Allow-Headers", req_allow_headers)); @@ -107,6 +107,67 @@ impl<'r, R: Responder<'r>> Responder<'r> for Cached { } } +// Log all the routes from the main base paths list, and the attachments endoint +// Effectively ignores, any static file route, and the alive endpoint +const LOGGED_ROUTES: [&str; 6] = [ + "/api", + "/admin", + "/identity", + "/icons", + "/notifications/hub/negotiate", + "/attachments", +]; + +// Boolean is extra debug, when true, we ignore the whitelist above and also print the mounts +pub struct BetterLogging(pub bool); +impl Fairing for BetterLogging { + fn info(&self) -> Info { + Info { + name: "Better Logging", + kind: Kind::Launch | Kind::Request | Kind::Response, + } + } + + fn on_launch(&self, rocket: &Rocket) { + if self.0 { + info!(target: "routes", "Routes loaded:"); + for route in rocket.routes() { + if route.rank < 0 { + info!(target: "routes", "{:<6} {}", route.method, route.uri); + } else { + info!(target: "routes", "{:<6} {} [{}]", route.method, route.uri, route.rank); + } + } + } + + let config = rocket.config(); + let scheme = if config.tls_enabled() { "https" } else { "http" }; + let addr = format!("{}://{}:{}", &scheme, &config.address, &config.port); + info!(target: "start", "Rocket has launched from {}", addr); + } + + fn on_request(&self, request: &mut Request<'_>, _data: &Data) { + let mut uri = request.uri().to_string(); + uri.truncate(50); + + if self.0 || LOGGED_ROUTES.iter().any(|r| uri.starts_with(r)) { + info!(target: "request", "{} {}", request.method(), uri); + } + } + + fn on_response(&self, request: &Request, response: &mut Response) { + let uri = request.uri().to_string(); + if self.0 || LOGGED_ROUTES.iter().any(|r| uri.starts_with(r)) { + let status = response.status(); + if let Some(ref route) = request.route() { + info!(target: "response", "{} => {} {}", route, status.code, status.reason) + } else { + info!(target: "response", "{} {}", status.code, status.reason) + } + } + } +} + // // File handling //