feat: switch to slog-mozlog-json/mozsvc-common for logging

limit the max log levels from external crates via the log crate (some
deps like tokio-core are too verbose), allowing travis tests to run in
rustc debug mode

also fix the default crypto_key setting (expects a String)

Closes #1247

.travis.yml

@@ -7,10 +7,6 @@ cache:
 sudo: required
 dist: trusty
 
-env:
-  global:
-    - WITH_RUST=release
-
 matrix:
   include:
     - python: 2.7
@@ -33,10 +29,12 @@ install:
       # Build here instead of within tox's pip install -e. It hides the output
       # which can kill the job on slower travis runs
       if [ ${WITH_RUST} == "release" ]; then
-          export CARGO_ARG="--release"
+          cargo build --manifest-path autopush_rs/Cargo.toml --release || \
+              travis_terminate 1
+      else
+          cargo build --manifest-path autopush_rs/Cargo.toml || \
+              travis_terminate 1
       fi
-      cargo build --manifest-path autopush_rs/Cargo.toml ${CARGO_ARG:-""} || \
-          travis_terminate 1
   fi
 script:
 - tox -v -- ${CODECOV:+--with-coverage --cover-xml --cover-package=autopush}

autopush/tests/test_rs_integration.py

@@ -114,7 +114,7 @@ def setup_module():
         auto_ping_timeout=10.0,
         close_handshake_timeout=5,
         max_connections=5000,
-        human_logs="false",
+        human_logs="true",
     )
     rust_bin = root_dir + "/target/release/autopush_rs"
     possible_paths = ["/target/debug/autopush_rs",

autopush_rs/Cargo.toml

@@ -28,16 +28,13 @@ fernet = "0.1.0"
 futures = "0.1.21"
 futures-backoff = "0.1.0"
 hex = "0.3.2"
-hostname = "0.1.5"
 httparse = "1.2.4"
 hyper = "0.11.27"
 lazy_static = "1.0.1"
 libc = "0.2.41"
-# log: Use this version for debug builds
-# log = "0.4.1"
-# log: Use this for release builds (leave in for commits)
-log = { version = "0.4.1", features = ["max_level_trace", "release_max_level_warn"] }
+log = { version = "0.4.1", features = ["max_level_info", "release_max_level_info"] }
 matches = "0.1.6"
+mozsvc-common = "0.1.0"
 openssl = "0.10.8"
 rand = "0.5.0"
 regex = "1.0.0"
@@ -50,13 +47,10 @@ serde = "1.0.63"
 serde_derive = "1.0.63"
 serde_dynamodb = "0.1.2"
 serde_json = "1.0.18"
-# slog: Use this first version for debug builds
-# slog = { version = "2.2.3" , features = ["max_level_trace", "release_max_level_debug"] }
-# slog: Use this for release builds (leave in for commits)
-slog = "2.2.3"
+slog = { version = "2.2.3" , features = ["max_level_trace", "release_max_level_info"] }
 slog-async = "2.3.0"
 slog-term = "2.4.0"
-slog-json = "2.2.0"
+slog-mozlog-json = "0.1"
 slog-scope = "4.0.1"
 slog-stdlog = "3.0.2"
 # state_machine_future = { version = "0.1.6", features = ["debug_code_generation"] }

autopush_rs/src/client.rs

@@ -311,7 +311,7 @@ where
     fn poll_await_hello<'a>(
         hello: &'a mut RentToOwn<'a, AwaitHello<T>>,
     ) -> Poll<AfterAwaitHello<T>, Error> {
-        debug!("State: AwaitHello");
+        trace!("State: AwaitHello");
         let (uaid, services) = {
             let AwaitHello {
                 ref mut data,
@@ -355,7 +355,7 @@ where
     fn poll_await_process_hello<'a>(
         process_hello: &'a mut RentToOwn<'a, AwaitProcessHello<T>>,
     ) -> Poll<AfterAwaitProcessHello<T>, Error> {
-        debug!("State: AwaitProcessHello");
+        trace!("State: AwaitProcessHello");
         let (uaid, message_month, check_storage, reset_uaid, rotate_message_table, connected_at) = {
             match try_ready!(process_hello.response.poll()) {
                 HelloResponse {
@@ -631,6 +631,7 @@ where
     fn poll_send_then_wait<'a>(
         send: &'a mut RentToOwn<'a, SendThenWait<T>>,
     ) -> Poll<AfterSendThenWait<T>, Error> {
+        trace!("State: SendThenWait");
         let start_send = {
             let SendThenWait {
                 ref mut remaining_data,
@@ -711,6 +712,7 @@ where
     fn poll_await_input<'a>(
         await: &'a mut RentToOwn<'a, AwaitInput<T>>,
     ) -> Poll<AfterAwaitInput<T>, Error> {
+        trace!("State: AwaitInput");
         let input = try_ready!(await.data.input_or_notif());
         let AwaitInput { data } = await.take();
         let webpush_rc = data.webpush.clone();
@@ -854,7 +856,7 @@ where
     fn poll_increment_storage<'a>(
         increment_storage: &'a mut RentToOwn<'a, IncrementStorage<T>>,
     ) -> Poll<AfterIncrementStorage<T>, Error> {
-        debug!("State: IncrementStorage");
+        trace!("State: IncrementStorage");
         let webpush_rc = increment_storage.data.webpush.clone();
         let webpush = webpush_rc.borrow();
         let timestamp = webpush
@@ -875,7 +877,7 @@ where
     fn poll_await_increment_storage<'a>(
         await_increment_storage: &'a mut RentToOwn<'a, AwaitIncrementStorage<T>>,
     ) -> Poll<AfterAwaitIncrementStorage<T>, Error> {
-        debug!("State: AwaitIncrementStorage");
+        trace!("State: AwaitIncrementStorage");
         try_ready!(await_increment_storage.response.poll());
         let AwaitIncrementStorage { data, .. } = await_increment_storage.take();
         let webpush = data.webpush.clone();
@@ -886,7 +888,7 @@ where
     fn poll_check_storage<'a>(
         check_storage: &'a mut RentToOwn<'a, CheckStorage<T>>,
     ) -> Poll<AfterCheckStorage<T>, Error> {
-        debug!("State: CheckStorage");
+        trace!("State: CheckStorage");
         let CheckStorage { data } = check_storage.take();
         let response = Box::new({
             let webpush = data.webpush.borrow();
@@ -903,7 +905,7 @@ where
     fn poll_await_check_storage<'a>(
         await_check_storage: &'a mut RentToOwn<'a, AwaitCheckStorage<T>>,
     ) -> Poll<AfterAwaitCheckStorage<T>, Error> {
-        debug!("State: AwaitCheckStorage");
+        trace!("State: AwaitCheckStorage");
         let (include_topic, mut messages, timestamp) =
             match try_ready!(await_check_storage.response.poll()) {
                 CheckStorageResponse {
@@ -951,7 +953,7 @@ where
     fn poll_await_migrate_user<'a>(
         await_migrate_user: &'a mut RentToOwn<'a, AwaitMigrateUser<T>>,
     ) -> Poll<AfterAwaitMigrateUser<T>, Error> {
-        debug!("State: AwaitMigrateUser");
+        trace!("State: AwaitMigrateUser");
         try_ready!(await_migrate_user.response.poll());
         let AwaitMigrateUser { data, .. } = await_migrate_user.take();
         {
@@ -965,15 +967,15 @@ where
     fn poll_await_drop_user<'a>(
         await_drop_user: &'a mut RentToOwn<'a, AwaitDropUser<T>>,
     ) -> Poll<AfterAwaitDropUser, Error> {
-        debug!("State: AwaitDropUser");
+        trace!("State: AwaitDropUser");
         try_ready!(await_drop_user.response.poll());
         transition!(AuthDone(()))
     }
 
     fn poll_await_register<'a>(
         await_register: &'a mut RentToOwn<'a, AwaitRegister<T>>,
     ) -> Poll<AfterAwaitRegister<T>, Error> {
-        debug!("State: AwaitRegister");
+        trace!("State: AwaitRegister");
         let msg = match try_ready!(await_register.response.poll()) {
             RegisterResponse::Success { endpoint } => {
                 let mut webpush = await_register.data.webpush.borrow_mut();
@@ -1010,7 +1012,7 @@ where
     fn poll_await_unregister<'a>(
         await_unregister: &'a mut RentToOwn<'a, AwaitUnregister<T>>,
     ) -> Poll<AfterAwaitUnregister<T>, Error> {
-        debug!("State: AwaitUnRegister");
+        trace!("State: AwaitUnRegister");
         let msg = if try_ready!(await_unregister.response.poll()) {
             debug!("Got the unregister response");
             let mut webpush = await_unregister.data.webpush.borrow_mut();
@@ -1043,7 +1045,7 @@ where
     fn poll_await_delete<'a>(
         await_delete: &'a mut RentToOwn<'a, AwaitDelete<T>>,
     ) -> Poll<AfterAwaitDelete<T>, Error> {
-        debug!("State: AwaitDelete");
+        trace!("State: AwaitDelete");
         try_ready!(await_delete.response.poll());
         transition!(DetermineAck {
             data: await_delete.take().data,

autopush_rs/src/lib.rs

@@ -71,14 +71,14 @@ extern crate fernet;
 extern crate futures;
 extern crate futures_backoff;
 extern crate hex;
-extern crate hostname;
 extern crate httparse;
 extern crate hyper;
 #[macro_use]
 extern crate lazy_static;
 extern crate libc;
 #[macro_use]
 extern crate matches;
+extern crate mozsvc_common;
 extern crate openssl;
 extern crate rand;
 extern crate regex;
@@ -96,7 +96,7 @@ extern crate serde_json;
 #[macro_use]
 extern crate slog;
 extern crate slog_async;
-extern crate slog_json;
+extern crate slog_mozlog_json;
 #[macro_use]
 extern crate slog_scope;
 extern crate slog_stdlog;
@@ -121,6 +121,7 @@ mod db;
 mod client;
 pub mod errors;
 mod http;
+mod logging;
 mod protocol;
 pub mod server;
 pub mod settings;

autopush_rs/src/logging.rs

@@ -0,0 +1,50 @@
+use std::io;
+
+use errors::Result;
+
+use mozsvc_common::{aws::get_ec2_instance_id, get_hostname};
+use slog::{self, Drain};
+use slog_async;
+use slog_mozlog_json::MozLogJson;
+use slog_scope;
+use slog_stdlog;
+use slog_term;
+
+pub fn init_logging(json: bool) -> Result<()> {
+    let logger = if json {
+        let hostname = get_ec2_instance_id()
+            .map(&str::to_owned)
+            .or_else(get_hostname)
+            .ok_or_else(|| "Couldn't get_hostname")?;
+
+        let drain = MozLogJson::new(io::stdout())
+            .logger_name(format!(
+                "{}-{}",
+                env!("CARGO_PKG_NAME"),
+                env!("CARGO_PKG_VERSION")
+            ))
+            .msg_type(format!("{}:log", env!("CARGO_PKG_NAME")))
+            .hostname(hostname)
+            .build()
+            .fuse();
+        let drain = slog_async::Async::new(drain).build().fuse();
+        slog::Logger::root(drain, slog_o!())
+    } else {
+        let decorator = slog_term::TermDecorator::new().build();
+        let drain = slog_term::FullFormat::new(decorator).build().fuse();
+        let drain = slog_async::Async::new(drain).build().fuse();
+        slog::Logger::root(drain, slog_o!())
+    };
+    // XXX: cancel slog_scope's NoGlobalLoggerSet for now, it's difficult to
+    // prevent it from potentially panicing during tests. reset_logging resets
+    // the global logger during shutdown anyway:
+    // https://github.com/slog-rs/slog/issues/169
+    slog_scope::set_global_logger(logger).cancel_reset();
+    slog_stdlog::init().ok();
+    Ok(())
+}
+
+pub fn reset_logging() {
+    let logger = slog::Logger::root(slog::Discard, o!());
+    slog_scope::set_global_logger(logger).cancel_reset();
+}