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.
This commit is contained in:
Daniel García 2019-12-06 22:19:07 +01:00
parent 912e1f93b7
commit 8d1b72b951
No known key found for this signature in database
GPG key ID: FC8A7D14C3CD543A
7 changed files with 130 additions and 53 deletions

View file

@ -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

View file

@ -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<Route> {
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")]

View file

@ -12,6 +12,8 @@ use crate::error::Error;
use crate::CONFIG;
pub fn routes() -> Vec<Route> {
// 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 {

View file

@ -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

View file

@ -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));
}};
}

View file

@ -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

View file

@ -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<R> {
}
}
// 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
//