Configurable logging contexts; refactored logging

Logging from each component (parsing, synthesis, HTTP server) now logs
as its own target. Configuration options enable turning on or off each
component so it's easy to isolate a component for debugging.

config.toml

@@ -1,4 +1,3 @@
-
 # Configs for the server.
 
 [default] # Production
@@ -8,7 +7,17 @@
   extra_dictionary_file = "./dictionary/extra-dict"
   square_dictionary_file = "./dictionary/square-dict"
 
+  # Logging verbosity
+  log_parsing = false
+  log_synthesis = false
+  log_handler = false
+
 [x16] # Local Development
   use_caching_headers = false
   sound_path = "/home/bt/Dropbox/jungle.horse/sounds"
 
+  # Logging verbosity
+  log_parsing = true
+  log_synthesis = false
+  log_handler = false
+

src/audiobank.rs

@@ -161,7 +161,8 @@ impl Audiobank {
 
       match self.read_wave_file(&pref_path) {
         Some(p) => {
-          info!("Used {:?} for {:?}", sample_preference, n_phone);
+          info!(target: "synthesis",
+                "Used {:?} for {:?}", sample_preference, n_phone);
           return Some(p)
         },
         None => {},

src/config.rs

@@ -1,4 +1,4 @@
-// Copyright (c) 2016 Brandon Thomas <bt@brand.io>
+// Copyright (c) 2016 Brandon Thomas <bt@brand.io, echelon@gmail.com>
 
 use resolve::hostname;
 use std::convert::From;
@@ -20,6 +20,11 @@ pub struct Config {
   pub phoneme_dictionary_file: Option<String>,
   pub extra_dictionary_file: Option<String>,
   pub square_dictionary_file: Option<String>,
+
+  /// What events to log.
+  pub log_handler: Option<bool>,
+  pub log_parsing: Option<bool>,
+  pub log_synthesis: Option<bool>,
 }
 
 #[derive(Debug)]
@@ -93,6 +98,15 @@ impl Config {
       square_dictionary_file: self.square_dictionary_file
           .clone()
           .or(other.square_dictionary_file.clone()),
+      log_handler: self.log_handler
+          .clone()
+          .or(other.log_handler.clone()),
+      log_parsing: self.log_parsing
+          .clone()
+          .or(other.log_parsing.clone()),
+      log_synthesis: self.log_synthesis
+          .clone()
+          .or(other.log_synthesis.clone()),
     }
   }
 }

src/handlers/audio_synth_handler.rs

@@ -279,8 +279,6 @@ impl SpeakRequest {
 impl Handler for AudioSynthHandler {
   /// Process request.
   fn handle(&self, req: &mut Request) -> IronResult<Response> {
-    info!("GET /speak");
-
     let sentence_error = build_error(status::BadRequest,
         &format!("Missing `{}` parameter.", SENTENCE_PARAM));
 
@@ -300,19 +298,19 @@ impl Handler for AudioSynthHandler {
       },
     };
 
-    info!("Speak Request ({}): {}.", request.speaker, request.sentence);
-    info!("Request: {:?}", request);
+    info!(target: "handler", "Speak Request: {:?}", request);
 
     // FIXME: Varies with spaces, formatting, etc.
     let hash = self.sha_digest(&request);
     let entity_tag = EntityTag::new(true, hash.to_owned());
 
-    info!("Request Header Caching Sha: {}", hash);
+    info!(target: "handler", "Request Header Caching Sha: {}", hash);
 
     if self.config.use_caching_headers.unwrap_or(true) {
       // Don't generate file if caching header is matched.
       if request_hash == entity_tag.to_string() {
-        info!("Caching headers match; responding with NotModified.");
+        info!(target: "handler",
+              "Caching headers match; responding with NotModified.");
         return Ok(Response::with(status::NotModified));
       }
     }

src/handlers/error_filter.rs

@@ -20,7 +20,7 @@ pub fn build_error(status: Status, message: &str) -> IronResult<Response> {
 
 impl AfterMiddleware for ErrorFilter {
   fn catch(&self, _: &mut Request, err: IronError) -> IronResult<Response> {
-    error!("Error has occurred! Error: {}", err.error);
+    error!(target: "handler", "Error has occurred! Error: {}", err.error);
 
     // TODO: Return JSON if request was JSON, otherwise HTML.
     match err.response.status {
@@ -39,8 +39,8 @@ impl fmt::Display for StringError {
 }
 
 impl Error for StringError {
-  fn description(&self) -> &str { 
-    &*self.0 
+  fn description(&self) -> &str {
+    &*self.0
   }
 }
 

src/handlers/file_server_handler.rs

@@ -25,7 +25,7 @@ pub struct FileServerHandler {
 impl Handler for FileServerHandler {
   /// Handles routes of the form `/f/:fileame`
   fn handle(&self, req: &mut Request) -> IronResult<Response> {
-    info!("Request: {}", &req.url);
+    info!(target: "handler", "Request: {}", &req.url);
 
     let filename = self.get_filename(&req);
 
@@ -101,7 +101,7 @@ impl FileServerHandler {
 
     // TODO: whitelist filetypes.
     // TODO: only open non-executable files.
-    info!("Opening file `{}`", full_filename.display());
+    debug!(target: "handler", "Opening file `{}`", full_filename.display());
 
     let mut file = match File::open(full_filename) {
       Err(_) => { return None },

src/lang/parser.rs

@@ -52,7 +52,7 @@ impl Parser {
 
     let final_sentence = sentence.join(" ");
 
-    info!("Final sentence: {}", final_sentence);
+    info!(target: "parsing", "Final sentence = {}", final_sentence);
 
     final_sentence
   }

src/lang/tokenizer.rs

@@ -191,6 +191,8 @@ impl Tokenizer {
 
   /// Split a raw sentence into well-defined tokens.
   pub fn tokenize(&self, raw_sentence: &str) -> Vec<Token> {
+    info!(target: "parsing", "Raw Sentence = {}", raw_sentence);
+
     // Remove any type of double quote
     let mut filtered = RE_ANY_DOUBLE_QUOTE.replace_all(raw_sentence, " ");
 
@@ -229,8 +231,6 @@ impl Tokenizer {
         continue;
       }
 
-      println!("Dictionary does not contain: {}", word);
-
       // TODO: TEST
       // Match URLs.
       if RE_URL.is_match(&word) {
@@ -383,8 +383,7 @@ impl Tokenizer {
       tokens.push(Token::unknown(word))
     }
 
-    //println!("TOKENS = {:?}", tokens);
-    info!("TOKENS = {:?}", tokens);
+    info!(target: "parsing", "Tokens = {:?}", tokens);
 
     tokens
   }

src/logger.rs

@@ -1,5 +1,6 @@
-// Copyright (c) 2015 Brandon Thomas <bt@brand.io>
+// Copyright (c) 2015-2016 Brandon Thomas <bt@brand.io, echelon@gmail.com>
 
+use config::Config;
 use log::LogLevel;
 use log::LogLevelFilter;
 use log::LogMetadata;
@@ -9,21 +10,33 @@ use log;
 use time::now;
 
 /// Simple logger example taken from rust-lang.org docs.
-pub struct SimpleLogger;
+pub struct SimpleLogger {
+  config: Config,
+}
 
 impl SimpleLogger {
+  pub fn new(config: Config) -> SimpleLogger {
+    SimpleLogger { config : config }
+  }
+
   /// Install the logger.
-  pub fn init() -> Result<(), SetLoggerError> {
+  pub fn init(&self) -> Result<(), SetLoggerError> {
     log::set_logger(|max_log_level| {
       max_log_level.set(LogLevelFilter::Info);
-      Box::new(SimpleLogger)
+      // TODO: This is ridiculous. Figure out trait objects, vtables, etc.
+      Box::new(SimpleLogger::new(self.config.clone()))
     })
   }
 }
 
 impl log::Log for SimpleLogger {
   fn enabled(&self, metadata: &LogMetadata) -> bool {
-    metadata.level() <= LogLevel::Info
+    match metadata.target() {
+      "handler" => self.config.log_handler.unwrap_or(false),
+      "parsing" => self.config.log_parsing.unwrap_or(false),
+      "synthesis" => self.config.log_synthesis.unwrap_or(false),
+      _ => metadata.level() <= LogLevel::Info,
+    }
   }
 
   fn log(&self, record: &LogRecord) {

src/main.rs

@@ -49,7 +49,9 @@ use std::sync::RwLock;
 use synthesizer::Synthesizer;
 
 fn main() {
-  SimpleLogger::init().unwrap();
+  let config = Config::read("./config.toml").unwrap();
+  let logger = SimpleLogger::new(config.clone());
+  logger.init().unwrap();
 
   // Parse command line args.
   let matches = App::new("trumpet")
@@ -63,8 +65,6 @@ fn main() {
 
   let port = get_port(&matches, 9000);
 
-  let config = Config::read("./config.toml").unwrap();
-
   VocabularyLibrary::read_from_directory(
       Path::new(&config.sound_path.clone().unwrap())).unwrap();
 

src/synthesizer.rs

@@ -188,7 +188,8 @@ impl Synthesizer {
     let polyphone = match self.arpabet_dictionary.get_polyphone(word) {
       Some(p) => { p },
       None => {
-        info!("Word '{}' does not exist in polyphone database.", word);
+        info!(target: "synthesis",
+              "Word '{}' does not exist in polyphone database.", word);
         // XXX: Adding static as a cue to denote that the given
         // word->polyphone mapping doesn't exist in the database.
         match self.audiobank.get_misc("record_static") {
@@ -201,7 +202,8 @@ impl Synthesizer {
       },
     };
 
-    info!("Word '{}' maps to polyphone '{:?}'", word, polyphone);
+    info!(target: "synthesis",
+          "Word '{}' maps to polyphone '{:?}'", word, polyphone);
 
     // Insert space before polyphone.
     match self.audiobank.get_misc("pause") {
@@ -228,7 +230,8 @@ impl Synthesizer {
         match self.audiobank.get_diphone(speaker.as_str(), first, second) {
           None => {},
           Some(diphone_data) => {
-            info!("Read diphone: {}, {}", first, second);
+            info!(target: "synthesis",
+                  "Read diphone: {}, {}", first, second);
             skip_next = true;
             concatenated_waveform.extend(diphone_data);
             continue;
@@ -385,7 +388,7 @@ impl Synthesizer {
       }
     }
 
-    info!("4-fulfilled: {:?}", fulfilled);
+    info!(target: "synthesis", "4-fulfilled: {:?}", fulfilled);
 
     // 3-phone
     if polyphone.len() >= 3 {
@@ -418,7 +421,7 @@ impl Synthesizer {
       }
     }
 
-    info!("3-fulfilled: {:?}", fulfilled);
+    info!(target: "synthesis", "3-fulfilled: {:?}", fulfilled);
 
     // 2-phone
     if polyphone.len() >= 2 {
@@ -451,7 +454,7 @@ impl Synthesizer {
       }
     }
 
-    info!("2-fulfilled: {:?}", fulfilled);
+    info!(target: "synthesis", "2-fulfilled: {:?}", fulfilled);
 
     // 1-phone
     for i in 0..polyphone.len() {
@@ -477,7 +480,7 @@ impl Synthesizer {
       }
     }
 
-    info!("1-fulfilled: {:?}", fulfilled);
+    info!(target: "synthesis", "1-fulfilled: {:?}", fulfilled);
 
     for x in fulfilled {
       if !x {
@@ -489,13 +492,13 @@ impl Synthesizer {
       .map(|x| if x.is_some() { x.unwrap() } else { "None".to_string() })
       .collect();
 
-    info!("Comprised of: {:?}", debug_str);
+    info!(target: "synthesis", "Comprised of: {:?}", debug_str);
 
     let results : Vec<SampleBytes> = chunks.into_iter()
       .filter_map(|x| x) // Woo, already Option<T>!
       .collect();
 
-    info!("Results Length: {} of {} phones",
+    info!(target: "synthesis", "Results Length: {} of {} phones",
           results.len(),
           polyphone.len());