Decent logging. Configurable log level.v0.2.0

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]]
@@ -62,17 +62,6 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -385,19 +374,6 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -730,15 +706,6 @@ 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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -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",
 ]
@@ -1254,16 +1221,6 @@ 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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1366,23 +1323,6 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1632,6 +1572,15 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1896,15 +1845,6 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1925,6 +1865,15 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2044,16 +1993,54 @@ 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"
 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]]
@@ -2184,6 +2171,12 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2365,15 +2358,6 @@ 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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
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<Bot>, message: Message, command: Command, db: Arc<DbPool>)
                 -> Result<(), Box<dyn Error + Send + Sync>> {
+    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<DbPool, sqlx::Error> {
     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<DbPool, sqlx::Error> {
                 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<Option<User>, 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<Option<User
 }
 
 pub async fn get_user_by_token(db: &DbPool, token: &str) -> Result<Option<User>, 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<Option<User>, 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<Extract=(DbPool, ), Error=Infallible> + Clone {
     warp::any().map(move || db_pool.clone())
@@ -29,13 +34,28 @@ fn with_bot(bot: Bot) -> impl Filter<Extract=(Bot, ), Error=Infallible> + 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<impl Reply, Rejection> {
-    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<impl Reply, Rejection> {
+    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))
 }