Merge #230

230: Logs r=MarinPostma a=irevoire

closes #193 

Since we can't really print the body of requests in actix-web, I logged the parameters of every request and what we were returning to the client.

Co-authored-by: Tamo <tamo@meilisearch.com>

meilisearch-http/src/index/search.rs

@@ -33,7 +33,7 @@ pub const fn default_crop_length() -> usize {
     DEFAULT_CROP_LENGTH
 }
 
-#[derive(Deserialize)]
+#[derive(Deserialize, Debug)]
 #[serde(rename_all = "camelCase", deny_unknown_fields)]
 pub struct SearchQuery {
     pub q: Option<String>,
@@ -62,7 +62,7 @@ pub struct SearchHit {
     pub matches_info: Option<MatchesInfo>,
 }
 
-#[derive(Serialize)]
+#[derive(Serialize, Debug)]
 #[serde(rename_all = "camelCase")]
 pub struct SearchResult {
     pub hits: Vec<SearchHit>,

meilisearch-http/src/index/updates.rs

@@ -4,7 +4,7 @@ use std::marker::PhantomData;
 use std::num::NonZeroUsize;
 
 use flate2::read::GzDecoder;
-use log::info;
+use log::{debug, info, trace};
 use milli::update::{IndexDocumentsMethod, UpdateBuilder, UpdateFormat};
 use serde::{Deserialize, Serialize, Serializer};
 
@@ -201,7 +201,7 @@ impl Index {
         update_builder: UpdateBuilder,
         primary_key: Option<&str>,
     ) -> Result<UpdateResult> {
-        info!("performing document addition");
+        trace!("performing document addition");
 
         // Set the primary key if not set already, ignore if already set.
         if let (None, Some(primary_key)) = (self.primary_key(txn)?, primary_key) {
@@ -215,7 +215,7 @@ impl Index {
         builder.index_documents_method(method);
 
         let indexing_callback =
-            |indexing_step, update_id| info!("update {}: {:?}", update_id, indexing_step);
+            |indexing_step, update_id| debug!("update {}: {:?}", update_id, indexing_step);
 
         let gzipped = false;
         let addition = match content {
@@ -300,7 +300,7 @@ impl Index {
         }
 
         builder.execute(|indexing_step, update_id| {
-            info!("update {}: {:?}", update_id, indexing_step)
+            debug!("update {}: {:?}", update_id, indexing_step)
         })?;
 
         Ok(UpdateResult::Other)

meilisearch-http/src/index_controller/dump_actor/actor.rs

@@ -5,7 +5,7 @@ use std::sync::Arc;
 use async_stream::stream;
 use chrono::Utc;
 use futures::{lock::Mutex, stream::StreamExt};
-use log::{error, info};
+use log::{error, trace};
 use tokio::sync::{mpsc, oneshot, RwLock};
 use update_actor::UpdateActorHandle;
 use uuid_resolver::UuidResolverHandle;
@@ -60,7 +60,7 @@ where
     }
 
     pub async fn run(mut self) {
-        info!("Started dump actor.");
+        trace!("Started dump actor.");
 
         let mut inbox = self
             .inbox
@@ -135,7 +135,7 @@ where
         match task_result {
             Ok(Ok(())) => {
                 dump_infos.done();
-                info!("Dump succeed");
+                trace!("Dump succeed");
             }
             Ok(Err(e)) => {
                 dump_infos.with_error(e.to_string());

meilisearch-http/src/index_controller/dump_actor/mod.rs

@@ -3,7 +3,7 @@ use std::path::{Path, PathBuf};
 
 use anyhow::Context;
 use chrono::{DateTime, Utc};
-use log::{info, warn};
+use log::{info, trace, warn};
 #[cfg(test)]
 use mockall::automock;
 use serde::{Deserialize, Serialize};
@@ -164,7 +164,7 @@ where
     P: UpdateActorHandle + Send + Sync + Clone + 'static,
 {
     async fn run(self) -> Result<()> {
-        info!("Performing dump.");
+        trace!("Performing dump.");
 
         create_dir_all(&self.path).await?;
 

meilisearch-http/src/index_controller/mod.rs

@@ -55,7 +55,7 @@ pub struct IndexSettings {
     pub primary_key: Option<String>,
 }
 
-#[derive(Serialize)]
+#[derive(Serialize, Debug)]
 #[serde(rename_all = "camelCase")]
 pub struct IndexStats {
     #[serde(skip)]
@@ -76,7 +76,7 @@ pub struct IndexController {
     dump_handle: dump_actor::DumpActorHandleImpl,
 }
 
-#[derive(Serialize)]
+#[derive(Serialize, Debug)]
 #[serde(rename_all = "camelCase")]
 pub struct Stats {
     pub database_size: u64,

meilisearch-http/src/index_controller/snapshot.rs

@@ -2,7 +2,7 @@ use std::path::{Path, PathBuf};
 use std::time::Duration;
 
 use anyhow::bail;
-use log::{error, info};
+use log::{error, info, trace};
 use tokio::fs;
 use tokio::task::spawn_blocking;
 use tokio::time::sleep;
@@ -47,14 +47,14 @@ where
         );
         loop {
             if let Err(e) = self.perform_snapshot().await {
-                error!("{}", e);
+                error!("Error while performing snapshot: {}", e);
             }
             sleep(self.snapshot_period).await;
         }
     }
 
     async fn perform_snapshot(&self) -> anyhow::Result<()> {
-        info!("Performing snapshot.");
+        trace!("Performing snapshot.");
 
         let snapshot_dir = self.snapshot_path.clone();
         fs::create_dir_all(&snapshot_dir).await?;
@@ -87,7 +87,7 @@ where
         })
         .await??;
 
-        info!("Created snapshot in {:?}.", snapshot_path);
+        trace!("Created snapshot in {:?}.", snapshot_path);
 
         Ok(())
     }

meilisearch-http/src/index_controller/update_actor/actor.rs

@@ -6,7 +6,7 @@ use std::sync::Arc;
 
 use async_stream::stream;
 use futures::StreamExt;
-use log::info;
+use log::{trace};
 use oxidized_json_checker::JsonChecker;
 use tokio::fs;
 use tokio::io::AsyncWriteExt;
@@ -61,7 +61,7 @@ where
     pub async fn run(mut self) {
         use UpdateMsg::*;
 
-        info!("Started update actor.");
+        trace!("Started update actor.");
 
         let mut inbox = self
             .inbox

meilisearch-http/src/index_controller/uuid_resolver/actor.rs

@@ -1,6 +1,6 @@
 use std::{collections::HashSet, path::PathBuf};
 
-use log::{info, warn};
+use log::{trace, warn};
 use tokio::sync::mpsc;
 use uuid::Uuid;
 
@@ -19,7 +19,7 @@ impl<S: UuidStore> UuidResolverActor<S> {
     pub async fn run(mut self) {
         use UuidResolveMsg::*;
 
-        info!("uuid resolver started");
+        trace!("uuid resolver started");
 
         loop {
             match self.inbox.recv().await {

meilisearch-http/src/main.rs

@@ -19,8 +19,12 @@ const SENTRY_DSN: &str = "https://5ddfa22b95f241198be2271aaf028653@sentry.io/306
 async fn main() -> Result<(), MainError> {
     let opt = Opt::from_args();
 
-    let mut log_builder =
-        env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("info"));
+    let mut log_builder = env_logger::Builder::new();
+    log_builder.parse_filters(&opt.log_level);
+    if opt.log_level == "info"  {
+        // if we are in info we only allow the warn log_level for milli
+        log_builder.filter_module("milli", log::LevelFilter::Warn);
+    }
 
     match opt.env.as_ref() {
         "production" => {

meilisearch-http/src/option.rs

@@ -188,6 +188,10 @@ pub struct Opt {
     #[structopt(long, conflicts_with = "import-snapshot")]
     pub import_dump: Option<PathBuf>,
 
+    /// Set the log level
+    #[structopt(long, env = "MEILI_LOG_LEVEL", default_value = "info")]
+    pub log_level: String,
+
     #[structopt(skip)]
     pub indexer_options: IndexerOpts,
 }

meilisearch-http/src/routes/document.rs

@@ -1,7 +1,7 @@
 use actix_web::{delete, get, post, put};
 use actix_web::{web, HttpResponse};
 use indexmap::IndexMap;
-use log::error;
+use log::{debug, error};
 use milli::update::{IndexDocumentsMethod, UpdateFormat};
 use serde::Deserialize;
 use serde_json::Value;
@@ -64,6 +64,7 @@ async fn get_document(
     let document = data
         .retrieve_document(index, id, None as Option<Vec<String>>)
         .await?;
+    debug!("returns: {:?}", document);
     Ok(HttpResponse::Ok().json(document))
 }
 
@@ -78,10 +79,11 @@ async fn delete_document(
     let update_status = data
         .delete_documents(path.index_uid.clone(), vec![path.document_id.clone()])
         .await?;
+    debug!("returns: {:?}", update_status);
     Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update_status.id() })))
 }
 
-#[derive(Deserialize)]
+#[derive(Deserialize, Debug)]
 #[serde(rename_all = "camelCase", deny_unknown_fields)]
 struct BrowseQuery {
     offset: Option<usize>,
@@ -95,6 +97,7 @@ async fn get_all_documents(
     path: web::Path<IndexParam>,
     params: web::Query<BrowseQuery>,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", params);
     let attributes_to_retrieve = params.attributes_to_retrieve.as_ref().and_then(|attrs| {
         let mut names = Vec::new();
         for name in attrs.split(',').map(String::from) {
@@ -114,10 +117,11 @@ async fn get_all_documents(
             attributes_to_retrieve,
         )
         .await?;
+    debug!("returns: {:?}", documents);
     Ok(HttpResponse::Ok().json(documents))
 }
 
-#[derive(Deserialize)]
+#[derive(Deserialize, Debug)]
 #[serde(rename_all = "camelCase", deny_unknown_fields)]
 struct UpdateDocumentsQuery {
     primary_key: Option<String>,
@@ -132,6 +136,7 @@ async fn add_documents(
     params: web::Query<UpdateDocumentsQuery>,
     body: Payload,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", params);
     let update_status = data
         .add_documents(
             path.into_inner().index_uid,
@@ -142,6 +147,7 @@ async fn add_documents(
         )
         .await?;
 
+    debug!("returns: {:?}", update_status);
     Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update_status.id() })))
 }
 
@@ -176,6 +182,7 @@ async fn update_documents(
     params: web::Query<UpdateDocumentsQuery>,
     body: Payload,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", params);
     let update = data
         .add_documents(
             path.into_inner().index_uid,
@@ -186,6 +193,7 @@ async fn update_documents(
         )
         .await?;
 
+    debug!("returns: {:?}", update);
     Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update.id() })))
 }
 
@@ -198,6 +206,7 @@ async fn delete_documents(
     path: web::Path<IndexParam>,
     body: web::Json<Vec<Value>>,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", body);
     let ids = body
         .iter()
         .map(|v| {
@@ -208,6 +217,7 @@ async fn delete_documents(
         .collect();
 
     let update_status = data.delete_documents(path.index_uid.clone(), ids).await?;
+    debug!("returns: {:?}", update_status);
     Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update_status.id() })))
 }
 
@@ -218,5 +228,6 @@ async fn clear_all_documents(
     path: web::Path<IndexParam>,
 ) -> Result<HttpResponse, ResponseError> {
     let update_status = data.clear_documents(path.index_uid.clone()).await?;
+    debug!("returns: {:?}", update_status);
     Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update_status.id() })))
 }

meilisearch-http/src/routes/dump.rs

@@ -1,5 +1,6 @@
 use actix_web::HttpResponse;
 use actix_web::{get, post, web};
+use log::debug;
 use serde::{Deserialize, Serialize};
 
 use crate::error::ResponseError;
@@ -14,6 +15,7 @@ pub fn services(cfg: &mut web::ServiceConfig) {
 async fn create_dump(data: web::Data<Data>) -> Result<HttpResponse, ResponseError> {
     let res = data.create_dump().await?;
 
+    debug!("returns: {:?}", res);
     Ok(HttpResponse::Accepted().json(res))
 }
 
@@ -35,5 +37,6 @@ async fn get_dump_status(
 ) -> Result<HttpResponse, ResponseError> {
     let res = data.dump_status(path.dump_uid.clone()).await?;
 
+    debug!("returns: {:?}", res);
     Ok(HttpResponse::Ok().json(res))
 }

meilisearch-http/src/routes/index.rs

@@ -1,6 +1,7 @@
 use actix_web::{delete, get, post, put};
 use actix_web::{web, HttpResponse};
 use chrono::{DateTime, Utc};
+use log::debug;
 use serde::{Deserialize, Serialize};
 
 use super::{IndexParam, UpdateStatusResponse};
@@ -21,6 +22,7 @@ pub fn services(cfg: &mut web::ServiceConfig) {
 #[get("/indexes", wrap = "Authentication::Private")]
 async fn list_indexes(data: web::Data<Data>) -> Result<HttpResponse, ResponseError> {
     let indexes = data.list_indexes().await?;
+    debug!("returns: {:?}", indexes);
     Ok(HttpResponse::Ok().json(indexes))
 }
 
@@ -30,6 +32,7 @@ async fn get_index(
     path: web::Path<IndexParam>,
 ) -> Result<HttpResponse, ResponseError> {
     let meta = data.index(path.index_uid.clone()).await?;
+    debug!("returns: {:?}", meta);
     Ok(HttpResponse::Ok().json(meta))
 }
 
@@ -45,8 +48,10 @@ async fn create_index(
     data: web::Data<Data>,
     body: web::Json<IndexCreateRequest>,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", body);
     let body = body.into_inner();
     let meta = data.create_index(body.uid, body.primary_key).await?;
+    debug!("returns: {:?}", meta);
     Ok(HttpResponse::Ok().json(meta))
 }
 
@@ -73,10 +78,12 @@ async fn update_index(
     path: web::Path<IndexParam>,
     body: web::Json<UpdateIndexRequest>,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", body);
     let body = body.into_inner();
     let meta = data
         .update_index(path.into_inner().index_uid, body.primary_key, body.uid)
         .await?;
+    debug!("returns: {:?}", meta);
     Ok(HttpResponse::Ok().json(meta))
 }
 
@@ -108,6 +115,7 @@ async fn get_update_status(
         .get_update_status(params.index_uid, params.update_id)
         .await?;
     let meta = UpdateStatusResponse::from(meta);
+    debug!("returns: {:?}", meta);
     Ok(HttpResponse::Ok().json(meta))
 }
 
@@ -122,5 +130,6 @@ async fn get_all_updates_status(
         .map(UpdateStatusResponse::from)
         .collect::<Vec<_>>();
 
+    debug!("returns: {:?}", metas);
     Ok(HttpResponse::Ok().json(metas))
 }

meilisearch-http/src/routes/search.rs

@@ -1,6 +1,7 @@
 use std::collections::{BTreeSet, HashSet};
 
 use actix_web::{get, post, web, HttpResponse};
+use log::debug;
 use serde::Deserialize;
 use serde_json::Value;
 
@@ -78,8 +79,10 @@ async fn search_with_url_query(
     path: web::Path<IndexParam>,
     params: web::Query<SearchQueryGet>,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("called with params: {:?}", params);
     let query = params.into_inner().into();
     let search_result = data.search(path.into_inner().index_uid, query).await?;
+    debug!("returns: {:?}", search_result);
     Ok(HttpResponse::Ok().json(search_result))
 }
 
@@ -89,8 +92,10 @@ async fn search_with_post(
     path: web::Path<IndexParam>,
     params: web::Json<SearchQuery>,
 ) -> Result<HttpResponse, ResponseError> {
+    debug!("search called with params: {:?}", params);
     let search_result = data
         .search(path.into_inner().index_uid, params.into_inner())
         .await?;
+    debug!("returns: {:?}", search_result);
     Ok(HttpResponse::Ok().json(search_result))
 }

meilisearch-http/src/routes/settings.rs

@@ -1,4 +1,5 @@
 use actix_web::{delete, get, post, web, HttpResponse};
+use log::debug;
 
 use crate::helpers::Authentication;
 use crate::index::Settings;
@@ -9,6 +10,7 @@ use crate::{error::ResponseError, index::Unchecked};
 macro_rules! make_setting_route {
     ($route:literal, $type:ty, $attr:ident, $camelcase_attr:literal) => {
         mod $attr {
+            use log::debug;
             use actix_web::{web, HttpResponse};
 
             use crate::data;
@@ -27,6 +29,7 @@ macro_rules! make_setting_route {
                     ..Default::default()
                 };
                 let update_status = data.update_settings(index_uid.into_inner(), settings, false).await?;
+                debug!("returns: {:?}", update_status);
                 Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update_status.id() })))
             }
 
@@ -42,6 +45,7 @@ macro_rules! make_setting_route {
                 };
 
                 let update_status = data.update_settings(index_uid.into_inner(), settings, true).await?;
+                debug!("returns: {:?}", update_status);
                 Ok(HttpResponse::Accepted().json(serde_json::json!({ "updateId": update_status.id() })))
             }
 
@@ -51,6 +55,7 @@ macro_rules! make_setting_route {
                 index_uid: actix_web::web::Path<String>,
             ) -> std::result::Result<HttpResponse, ResponseError> {
                 let settings = data.settings(index_uid.into_inner()).await?;
+                debug!("returns: {:?}", settings);
                 let mut json = serde_json::json!(&settings);
                 let val = json[$camelcase_attr].take();
                 Ok(HttpResponse::Ok().json(val))
@@ -145,6 +150,7 @@ async fn update_all(
         .update_settings(index_uid.into_inner(), settings, true)
         .await?;
     let json = serde_json::json!({ "updateId": update_result.id() });
+    debug!("returns: {:?}", json);
     Ok(HttpResponse::Accepted().json(json))
 }
 
@@ -154,6 +160,7 @@ async fn get_all(
     index_uid: web::Path<String>,
 ) -> Result<HttpResponse, ResponseError> {
     let settings = data.settings(index_uid.into_inner()).await?;
+    debug!("returns: {:?}", settings);
     Ok(HttpResponse::Ok().json(settings))
 }
 
@@ -167,5 +174,6 @@ async fn delete_all(
         .update_settings(index_uid.into_inner(), settings, false)
         .await?;
     let json = serde_json::json!({ "updateId": update_result.id() });
+    debug!("returns: {:?}", json);
     Ok(HttpResponse::Accepted().json(json))
 }

meilisearch-http/src/routes/stats.rs

@@ -1,6 +1,7 @@
 use actix_web::get;
 use actix_web::web;
 use actix_web::HttpResponse;
+use log::debug;
 use serde::Serialize;
 
 use crate::error::ResponseError;
@@ -21,6 +22,7 @@ async fn get_index_stats(
 ) -> Result<HttpResponse, ResponseError> {
     let response = data.get_index_stats(path.index_uid.clone()).await?;
 
+    debug!("returns: {:?}", response);
     Ok(HttpResponse::Ok().json(response))
 }
 
@@ -28,6 +30,7 @@ async fn get_index_stats(
 async fn get_stats(data: web::Data<Data>) -> Result<HttpResponse, ResponseError> {
     let response = data.get_all_stats().await?;
 
+    debug!("returns: {:?}", response);
     Ok(HttpResponse::Ok().json(response))
 }
 

meilisearch-http/tests/common/server.rs

@@ -91,5 +91,6 @@ pub fn default_settings(dir: impl AsRef<Path>) -> Opt {
         snapshot_interval_sec: 0,
         import_dump: None,
         indexer_options: IndexerOpts::default(),
+        log_level: "off".into(),
     }
 }