From b611e395a2d002c0696c2c10e2f43b3f9013c6d9 Mon Sep 17 00:00:00 2001 From: Keuin Date: Mon, 28 Mar 2022 00:06:58 +0800 Subject: Decent logging. Configurable log level. --- Cargo.lock | 152 +++++++++++++++++++++++++------------------------------- Cargo.toml | 6 +-- src/bot.rs | 45 ++++++++++++----- src/config.rs | 18 +++++-- src/database.rs | 15 ++++-- src/main.rs | 42 ++++++++++++---- src/user.rs | 10 ++++ src/web.rs | 42 +++++++++++----- 8 files changed, 199 insertions(+), 131 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 0cda8f7..431d2f8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -20,12 +20,12 @@ dependencies = [ ] [[package]] -name = "aho-corasick" -version = "0.7.18" +name = "ansi_term" +version = "0.12.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1e37cfd5e7657ada45f742d6e99ca5788580b5c529dc78faf11ece6dc702656f" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" dependencies = [ - "memchr", + "winapi", ] [[package]] @@ -61,17 +61,6 @@ dependencies = [ "num-traits", ] -[[package]] -name = "atty" -version = "0.2.14" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8" -dependencies = [ - "hermit-abi", - "libc", - "winapi", -] - [[package]] name = "autocfg" version = "1.1.0" @@ -384,19 +373,6 @@ dependencies = [ "cfg-if 1.0.0", ] -[[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 = "erasable" version = "1.2.1" @@ -729,15 +705,6 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421" -[[package]] -name = "humantime" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" -dependencies = [ - "quick-error", -] - [[package]] name = "hyper" version = "0.14.18" @@ -856,14 +823,14 @@ version = "0.1.0" dependencies = [ "bs58", "futures", - "log", - "pretty_env_logger", "serde", "serde_derive", "serde_json", "sqlx", "teloxide", "tokio", + "tracing", + "tracing-subscriber", "urandom", "warp", ] @@ -1253,16 +1220,6 @@ version = "0.2.16" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "eb9f9e6e233e5c4a35559a617bf40a4ec447db2e84c20b55a6f83167b7e57872" -[[package]] -name = "pretty_env_logger" -version = "0.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" -dependencies = [ - "env_logger", - "log", -] - [[package]] name = "proc-macro-error" version = "1.0.4" @@ -1365,23 +1322,6 @@ dependencies = [ "bitflags", ] -[[package]] -name = "regex" -version = "1.5.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1a11647b6b25ff05a515cb92c365cec08801e83423a235b51e231e1808747286" -dependencies = [ - "aho-corasick", - "memchr", - "regex-syntax", -] - -[[package]] -name = "regex-syntax" -version = "0.6.25" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f497285884f3fcff424ffc933e56d7cbca511def0c9831a7f9b5f6153e3cc89b" - [[package]] name = "remove_dir_all" version = "0.5.3" @@ -1631,6 +1571,15 @@ dependencies = [ "opaque-debug", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook-registry" version = "1.4.0" @@ -1895,15 +1844,6 @@ dependencies = [ "winapi", ] -[[package]] -name = "termcolor" -version = "1.1.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "bab24d30b911b2376f3a13cc2cd443142f0c81dda04c118693e35b3835757755" -dependencies = [ - "winapi-util", -] - [[package]] name = "thiserror" version = "1.0.30" @@ -1924,6 +1864,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" +dependencies = [ + "once_cell", +] + [[package]] name = "tinyvec" version = "1.5.1" @@ -2044,9 +1993,21 @@ dependencies = [ "cfg-if 1.0.0", "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.20" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2e65ce065b4b5c53e73bb28912318cb8c9e9ad3921f1d669eb0e68b4c8143a2b" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "tracing-core" version = "0.1.23" @@ -2054,6 +2015,32 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "aa31669fa42c09c34d94d8165dd2012e8ff3c66aca50f3bb226b68f216f2706c" dependencies = [ "lazy_static", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9e0ab7bdc962035a87fba73f3acca9b8a8d0034c2e6f60b84aeaaddddc155dce" +dependencies = [ + "ansi_term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", ] [[package]] @@ -2183,6 +2170,12 @@ dependencies = [ "getrandom 0.2.5", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" @@ -2364,15 +2357,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", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index a635cd6..fd98da7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -10,11 +10,11 @@ tokio = { version = "1.17.0", features = ["full"] } futures = "0.3.21" warp = "0.3.2" teloxide = { version = "0.7.2", features = ["macros", "auto-send"] } -log = "0.4.16" -pretty_env_logger = "0.4.0" serde = "1.0.136" serde_derive = "1.0.136" serde_json = "1.0.79" sqlx = { version = "0.5", features = [ "runtime-tokio-rustls", "sqlite" ] } urandom = "0.1.0" -bs58 = "0.4.0" \ No newline at end of file +bs58 = "0.4.0" +tracing = "0.1.32" +tracing-subscriber = "0.3.9" \ No newline at end of file diff --git a/src/bot.rs b/src/bot.rs index 9ea2c3a..e46ed85 100644 --- a/src/bot.rs +++ b/src/bot.rs @@ -3,6 +3,7 @@ use std::ops::Deref; use std::sync::Arc; use teloxide::{prelude2::*, types::MessageKind, utils::command::BotCommand}; +use tracing::{debug, error, info}; use crate::{database, DbPool, token}; use crate::user::User; @@ -18,36 +19,54 @@ enum Command { async fn answer(bot: AutoSend, message: Message, command: Command, db: Arc) -> Result<(), Box> { + debug!("Answering telegram message: {:?}", message); match command { Command::Help => { - bot.send_message(message.chat.id, Command::descriptions()).await?; + debug!("Command /help."); + if let Err(why) = + bot.send_message(message.chat.id, Command::descriptions()).await { + error!("Failed to send telegram message: {:?}.", why); + } } Command::Start => { + debug!("Command /start."); if let MessageKind::Common(msg) = message.kind { if msg.from.is_none() { + debug!("Ignore message from channel."); return Ok(()); // ignore messages from channel } let from = msg.from.unwrap(); let db = db.deref(); let chat_id = message.chat.id; - match database::create_user(db, User { + let user = User { id: from.id as u64, name: from.username.unwrap_or_else(|| String::from("")), token: token::generate(), chat_id: chat_id as u64, - }).await { - Ok(_) => {} - Err(why) => println!("cannot create user: {:?}", why), + }; + if let Err(why) = database::create_user(db, &user).await { + if format!("{:?}", why).contains("UNIQUE constraint failed") { + info!("User exists: {}", user); + } else { + error!("Failed to create user {}: {:?}. Skip creating.", user, why); + } + } else { + info!("Created user {}.", user); } - bot.send_message( - chat_id, - match database::get_user_by_chat_id(db, chat_id as u64).await? { - Some(user) => - format!("Your token is `{}`. Treat it as a secret!", user.token), - _ => + let message = + match database::get_user_by_chat_id(db, chat_id as u64).await { + Ok(u) => match u { + Some(user) => format!("Your token is `{}`. Treat it as a secret!", user.token), + _ => String::from("Error: cannot fetch token.") + }, + Err(why) => { + error!("Cannot get user: {:?}.", why); String::from("Error: cannot fetch token.") - }, - ).await?; + } + }; + if let Err(why) = bot.send_message(chat_id, message).await { + error!("Failed to send telegram message: {:?}.", why); + } } } }; diff --git a/src/config.rs b/src/config.rs index c5d07a7..99e5f3d 100644 --- a/src/config.rs +++ b/src/config.rs @@ -2,6 +2,7 @@ use std::fs::File; use std::io::Read; use serde_derive::Deserialize; +use tracing::error; #[derive(Deserialize)] pub struct Config { @@ -9,17 +10,26 @@ pub struct Config { pub log_file: String, pub db_file: String, pub listen: String, + pub log_level: String, } impl Config { // Read config file. Panic if any error occurs. pub fn from_file(file_path: &str) -> Config { let mut file = File::open(file_path) - .unwrap_or_else(|_| panic!("cannot open file {}", file_path)); + .unwrap_or_else(|err| { + error!("Cannot open config file {}: {:?}", file_path, err); + panic!(); + }); let mut config = String::new(); file.read_to_string(&mut config) - .unwrap_or_else(|_| panic!("cannot read config file {}", file_path)); - return serde_json::from_str(config.as_str()) - .expect("cannot decode config file in JSON"); + .unwrap_or_else(|err| { + error!("Cannot read config file {}: {:?}.", file_path, err); + panic!(); + }); + return serde_json::from_str(config.as_str()).unwrap_or_else(|err| { + error!("Cannot decode config file: {:?}.", err); + panic!(); + }); } } \ No newline at end of file diff --git a/src/database.rs b/src/database.rs index edb2fc7..a73aafd 100644 --- a/src/database.rs +++ b/src/database.rs @@ -1,9 +1,9 @@ use std::str::FromStr; use futures::TryStreamExt; -use log::{debug, error, info, warn}; use sqlx::Row; use sqlx::sqlite::{SqliteConnectOptions, SqlitePoolOptions}; +use tracing::debug; use crate::user::User; @@ -15,11 +15,13 @@ pub async fn open(file_path: &str) -> Result { let opt = SqliteConnectOptions::from_str(format!("sqlite://{}", file_path).as_str())? .create_if_missing(true); + debug!("Opening database pool..."); let pool = SqlitePoolOptions::new() .max_connections(SQLITE_THREAD_POOL_SIZE) .connect_with(opt).await?; // create table + debug!("Creating user table if not exist..."); sqlx::query(r#"CREATE TABLE IF NOT EXISTS "user" ( "id" INTEGER NOT NULL CHECK(id >= 0) UNIQUE, "name" TEXT, @@ -28,10 +30,12 @@ pub async fn open(file_path: &str) -> Result { PRIMARY KEY("id","token","chat_id") )"#).execute(&pool).await?; + debug!("Finish opening database."); Ok(pool) } pub async fn get_user(db: &DbPool, sql: &str, param: &str) -> Result, sqlx::Error> { + debug!(sql, param, "Database query."); let mut rows = sqlx::query(sql) .bind(param).fetch(db); @@ -52,20 +56,23 @@ pub async fn get_user(db: &DbPool, sql: &str, param: &str) -> Result Result, sqlx::Error> { + debug!(token, "Get user by token."); get_user(db, "SELECT id, name, token, chat_id FROM user WHERE token=$1 LIMIT 1", token).await } pub async fn get_user_by_chat_id(db: &DbPool, chat_id: u64) -> Result, sqlx::Error> { + debug!(chat_id, "Get user by chat_id."); get_user(db, "SELECT id, name, token, chat_id FROM user WHERE chat_id=$1 LIMIT 1", chat_id.to_string().as_str()).await } -pub async fn create_user(db: &DbPool, user: User) -> sqlx::Result<()> { +pub async fn create_user(db: &DbPool, user: &User) -> sqlx::Result<()> { + debug!("Create user: {}", user); sqlx::query("INSERT INTO user (id, name, token, chat_id) VALUES ($1,$2,$3,$4)") .bind(user.id.to_string()) - .bind(user.name) - .bind(user.token) + .bind(user.name.clone()) + .bind(user.token.clone()) .bind(user.chat_id.to_string()) .execute(db).await?; Ok(()) diff --git a/src/main.rs b/src/main.rs index ad5fdf3..f67a6bc 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,9 +1,13 @@ use std::convert::Infallible; use std::net::SocketAddr; +use std::ops::Deref; +use std::str::FromStr; use std::sync::Arc; -use log::{debug, error, info, warn}; use teloxide::prelude2::*; +use tracing::{debug, info, Level}; +use tracing::instrument; +use tracing_subscriber::FmtSubscriber; use warp::Filter; use config::Config; @@ -19,6 +23,7 @@ mod config; const CONFIG_FILE_NAME: &str = "kimikuri.json"; const MAX_BODY_LENGTH: u64 = 1024 * 16; +const DEFAULT_LOG_LEVEL: Level = Level::DEBUG; fn with_db(db_pool: DbPool) -> impl Filter + Clone { warp::any().map(move || db_pool.clone()) @@ -29,13 +34,28 @@ fn with_bot(bot: Bot) -> impl Filter + Clone warp::any().map(move || bot.clone()) } +#[instrument] #[tokio::main] async fn main() { - pretty_env_logger::init(); - debug!("Loading bot config."); + eprintln!("Loading configuration file {}...", CONFIG_FILE_NAME); + // TODO make some fields optional let config = Config::from_file(CONFIG_FILE_NAME); - info!("Starting bot."); - let bot = Bot::new(config.bot_token); + + // configure logger + let log_level = match Level::from_str(&*config.log_level) { + Ok(l) => l, + Err(_) => { + eprintln!("Invalid log level: {}. Use {:?} instead.", + config.log_level, DEFAULT_LOG_LEVEL); + DEFAULT_LOG_LEVEL + } + }; + eprintln!("Configuration is loaded. Set log level to {:?}.", log_level); + let subscriber = FmtSubscriber::builder() + .with_max_level(log_level) + .finish(); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to set default subscriber"); let db = config.db_file.as_str(); info!(db, "Opening database..."); @@ -51,18 +71,18 @@ async fn main() { .and(with_db(db.deref().clone())) .and(with_bot(bot.clone())) .and_then(web::handler); + tokio::spawn(bot::repl(bot, db.clone())); - tokio::spawn(bot::repl(bot, Arc::new(db))); - + info!("Starting HTTP server..."); let endpoint: SocketAddr = config.listen.parse() .expect("Cannot parse `listen` as endpoint."); - - println!("Listen on {}", endpoint); - + info!("Start listening on {}", endpoint); tokio::spawn(warp::serve(send_message).run(endpoint)); + debug!("Waiting for Ctrl-C in main coroutine..."); tokio::signal::ctrl_c().await.unwrap(); - + // gracefully shutdown the database connection + info!("Closing database..."); db.deref().close().await; } diff --git a/src/user.rs b/src/user.rs index aef43fa..fb4adc7 100644 --- a/src/user.rs +++ b/src/user.rs @@ -1,6 +1,16 @@ +use std::fmt; +use std::fmt::Formatter; + pub struct User { pub id: u64, pub name: String, pub token: String, pub chat_id: u64, +} + +impl fmt::Display for User { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + write!(f, "User {{ id={}, name={}, token={}, chat_id={} }}", + self.id, self.name, self.token, self.chat_id) + } } \ No newline at end of file diff --git a/src/web.rs b/src/web.rs index 8b6505b..9ec73fd 100644 --- a/src/web.rs +++ b/src/web.rs @@ -1,5 +1,9 @@ +use std::fmt; +use std::fmt::Formatter; + use serde_derive::{Deserialize, Serialize}; use teloxide::{prelude2::*}; +use tracing::{debug, error, info, warn}; use warp::{Rejection, Reply}; use crate::{Bot, database, DbPool}; @@ -10,21 +14,33 @@ pub struct SendMessage { message: String, } +impl fmt::Display for SendMessage { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + write!(f, "SendMessage {{ token={}, message={} }}", self.token, self.message) + } +} + #[derive(Deserialize, Serialize)] pub struct SendMessageResponse { success: bool, message: String, } -pub async fn handler(req: SendMessage, db: DbPool, bot: Bot) -> std::result::Result { - println!("Token: {}, Message: {}", req.token, req.message); - let user = database::get_user_by_token(&db, req.token.as_str()).await; - Ok(warp::reply::json(&match user { +impl fmt::Display for SendMessageResponse { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + write!(f, "SendMessageResponse {{ success={}, message={} }}", self.success, self.message) + } +} + +pub async fn handler(req: SendMessage, db: DbPool, bot: Bot) + -> std::result::Result { + info!("Income API request: {}", req); + let user = + database::get_user_by_token(&db, req.token.as_str()).await; + let response = match user { Ok(u) => match u { Some(user) => { - log::info!("User: {} (id={}), message: {}", - user.name, user.id, req.message); - // TODO send message to Telegram + info!("Send message to user {}.", user); let bot = bot.auto_send(); match bot.send_message(user.chat_id as i64, req.message).await { Ok(_) => SendMessageResponse { @@ -32,7 +48,7 @@ pub async fn handler(req: SendMessage, db: DbPool, bot: Bot) -> std::result::Res message: String::new(), }, Err(why) => { - println!("Failed to send message to telegram: {:?}", why); + error!("Failed to send message to telegram: {:?}", why); SendMessageResponse { success: false, message: String::from("Failed to send message to telegram."), @@ -41,19 +57,21 @@ pub async fn handler(req: SendMessage, db: DbPool, bot: Bot) -> std::result::Res } } None => { - log::warn!("Invalid token {}, message: {}", req.token, req.message); + warn!("Invalid token: {}.", req); SendMessageResponse { success: false, message: String::from("Invalid token."), } } }, - Err(_) => { - log::error!("Error when querying the database."); + Err(err) => { + error!("Error when querying the database: {:?}.", err); SendMessageResponse { success: false, message: String::from("Invalid parameter."), } } - })) + }; + debug!("Response: {}", response); + Ok(warp::reply::json(&response)) } -- cgit v1.2.3