Driver: Reduce logging level in general (#48)

This change reduces many log levels to debug, particularly where errors are likely to be triggered by undocumented Discord messages or by threads exiting in an unpredictable way. This also reduces the task entry/exit messages to `trace`.

This PR has been tested via `cargo make ready`, and by manually inspecting logs at `debug` and `info` levels running `examples/serenity/voice`.

src/driver/tasks/events.rs

@@ -117,5 +117,5 @@ pub(crate) async fn runner(_interconnect: Interconnect, evt_rx: Receiver<EventMe
         }
     }
 
-    info!("Event thread exited.");
+    trace!("Event thread exited.");
 }

src/driver/tasks/message/mod.rs

@@ -15,7 +15,7 @@ use flume::Sender;
 use tokio::spawn;
 #[cfg(feature = "tokio-02-marker")]
 use tokio_compat::spawn;
-use tracing::info;
+use tracing::trace;
 
 #[derive(Clone, Debug)]
 pub struct Interconnect {
@@ -43,9 +43,9 @@ impl Interconnect {
 
         let ic = self.clone();
         spawn(async move {
-            info!("Event processor restarted.");
+            trace!("Event processor restarted.");
             super::events::runner(ic, evt_rx).await;
-            info!("Event processor finished.");
+            trace!("Event processor finished.");
         });
 
         // Make mixer aware of new targets...

src/driver/tasks/mixer.rs

@@ -22,7 +22,7 @@ use std::time::Instant;
 use tokio::runtime::Handle;
 #[cfg(feature = "tokio-02-marker")]
 use tokio_compat::runtime::Handle;
-use tracing::{error, instrument};
+use tracing::{debug, error, instrument};
 use xsalsa20poly1305::TAG_SIZE;
 
 pub struct Mixer {
@@ -111,8 +111,6 @@ impl Mixer {
         'runner: loop {
             if self.conn_active.is_some() {
                 loop {
-                    use MixerMessage::*;
-
                     match self.mix_rx.try_recv() {
                         Ok(m) => {
                             let (events, conn, should_exit) = self.handle_message(m);
@@ -138,7 +136,7 @@ impl Mixer {
                     events_failure |= e.should_trigger_interconnect_rebuild();
                     conn_failure |= e.should_trigger_connect();
 
-                    error!("Mixer thread cycle: {:?}", e);
+                    debug!("Mixer thread cycle: {:?}", e);
                 }
             } else {
                 match self.mix_rx.recv() {

src/driver/tasks/mod.rs

@@ -20,13 +20,13 @@ use message::*;
 use tokio::{runtime::Handle, spawn};
 #[cfg(feature = "tokio-02-marker")]
 use tokio_compat::{runtime::Handle, spawn};
-use tracing::{error, info, instrument};
+use tracing::{error, instrument, trace};
 
 pub(crate) fn start(config: Config, rx: Receiver<CoreMessage>, tx: Sender<CoreMessage>) {
     spawn(async move {
-        info!("Driver started.");
+        trace!("Driver started.");
         runner(config, rx, tx).await;
-        info!("Driver finished.");
+        trace!("Driver finished.");
     });
 }
 
@@ -42,17 +42,17 @@ fn start_internals(core: Sender<CoreMessage>, config: Config) -> Interconnect {
 
     let ic = interconnect.clone();
     spawn(async move {
-        info!("Event processor started.");
+        trace!("Event processor started.");
         events::runner(ic, evt_rx).await;
-        info!("Event processor finished.");
+        trace!("Event processor finished.");
     });
 
     let ic = interconnect.clone();
     let handle = Handle::current();
     std::thread::spawn(move || {
-        info!("Mixer started.");
+        trace!("Mixer started.");
         mixer::runner(ic, mix_rx, handle, config);
-        info!("Mixer finished.");
+        trace!("Mixer finished.");
     });
 
     interconnect
@@ -204,6 +204,6 @@ async fn runner(mut config: Config, rx: Receiver<CoreMessage>, tx: Sender<CoreMe
         }
     }
 
-    info!("Main thread exited");
+    trace!("Main thread exited");
     interconnect.poison_all();
 }

src/driver/tasks/udp_rx.rs

@@ -25,7 +25,7 @@ use std::{collections::HashMap, sync::Arc};
 use tokio::{net::UdpSocket, select};
 #[cfg(feature = "tokio-02-marker")]
 use tokio_compat::{net::udp::RecvHalf, select};
-use tracing::{error, info, instrument, warn};
+use tracing::{error, instrument, trace, warn};
 use xsalsa20poly1305::XSalsa20Poly1305 as Cipher;
 
 #[derive(Debug)]
@@ -401,7 +401,7 @@ pub(crate) async fn runner(
     config: Config,
     udp_socket: Arc<UdpSocket>,
 ) {
-    info!("UDP receive handle started.");
+    trace!("UDP receive handle started.");
 
     let mut state = UdpRx {
         cipher,
@@ -414,7 +414,7 @@ pub(crate) async fn runner(
 
     state.run(&mut interconnect).await;
 
-    info!("UDP receive handle stopped.");
+    trace!("UDP receive handle stopped.");
 }
 
 #[cfg(feature = "tokio-02-marker")]
@@ -426,7 +426,7 @@ pub(crate) async fn runner(
     config: Config,
     udp_socket: RecvHalf,
 ) {
-    info!("UDP receive handle started.");
+    trace!("UDP receive handle started.");
 
     let mut state = UdpRx {
         cipher,
@@ -439,7 +439,7 @@ pub(crate) async fn runner(
 
     state.run(&mut interconnect).await;
 
-    info!("UDP receive handle stopped.");
+    trace!("UDP receive handle stopped.");
 }
 
 #[inline]

src/driver/tasks/udp_tx.rs

@@ -13,7 +13,7 @@ use tokio_compat::{
     net::udp::SendHalf,
     time::{timeout_at, Instant},
 };
-use tracing::{error, info, instrument, trace};
+use tracing::{error, instrument, trace};
 
 struct UdpTx {
     ssrc: u32,
@@ -65,7 +65,7 @@ impl UdpTx {
 #[cfg(not(feature = "tokio-02-marker"))]
 #[instrument(skip(udp_msg_rx))]
 pub(crate) async fn runner(udp_msg_rx: Receiver<UdpTxMessage>, ssrc: u32, udp_tx: Arc<UdpSocket>) {
-    info!("UDP transmit handle started.");
+    trace!("UDP transmit handle started.");
 
     let mut txer = UdpTx {
         ssrc,
@@ -75,13 +75,13 @@ pub(crate) async fn runner(udp_msg_rx: Receiver<UdpTxMessage>, ssrc: u32, udp_tx
 
     txer.run().await;
 
-    info!("UDP transmit handle stopped.");
+    trace!("UDP transmit handle stopped.");
 }
 
 #[cfg(feature = "tokio-02-marker")]
 #[instrument(skip(udp_msg_rx))]
 pub(crate) async fn runner(udp_msg_rx: Receiver<UdpTxMessage>, ssrc: u32, udp_tx: SendHalf) {
-    info!("UDP transmit handle started.");
+    trace!("UDP transmit handle started.");
 
     let mut txer = UdpTx {
         ssrc,
@@ -91,5 +91,5 @@ pub(crate) async fn runner(udp_msg_rx: Receiver<UdpTxMessage>, ssrc: u32, udp_tx
 
     txer.run().await;
 
-    info!("UDP transmit handle stopped.");
+    trace!("UDP transmit handle stopped.");
 }

src/driver/tasks/ws.rs

@@ -27,7 +27,7 @@ use tokio_compat::{
     select,
     time::{delay_until as sleep_until, Instant},
 };
-use tracing::{error, info, instrument, trace, warn};
+use tracing::{debug, info, instrument, trace, warn};
 
 struct AuxNetwork {
     rx: Receiver<WsMessage>,
@@ -85,7 +85,7 @@ impl AuxNetwork {
                 ws_msg = self.ws_client.recv_json_no_timeout(), if !self.dont_send => {
                     ws_error = match ws_msg {
                         Err(WsError::Json(e)) => {
-                            warn!("Unexpected JSON {:?}.", e);
+                            debug!("Unexpected JSON {:?}.", e);
                             false
                         },
                         Err(e) => {
@@ -218,11 +218,11 @@ pub(crate) async fn runner(
     ssrc: u32,
     heartbeat_interval: f64,
 ) {
-    info!("WS thread started.");
+    trace!("WS thread started.");
     let mut aux = AuxNetwork::new(evt_rx, ws_client, ssrc, heartbeat_interval);
 
     aux.run(&mut interconnect).await;
-    info!("WS thread finished.");
+    trace!("WS thread finished.");
 }
 
 fn ws_error_is_not_final(err: WsError) -> bool {
@@ -237,7 +237,7 @@ fn ws_error_is_not_final(err: WsError) -> bool {
             _ => true,
         },
         e => {
-            error!("Error sending/receiving ws {:?}.", e);
+            debug!("Error sending/receiving ws {:?}.", e);
             true
         },
     }

src/ws.rs

@@ -26,7 +26,7 @@ use serde_json::Error as JsonError;
 use tokio::time::{timeout, Duration};
 #[cfg(feature = "tokio-02-marker")]
 use tokio_compat::time::{timeout, Duration};
-use tracing::{instrument, warn};
+use tracing::instrument;
 
 pub type WsStream = WebSocketStream<ConnectStream>;
 
@@ -130,12 +130,7 @@ impl SenderExt for WsStream {
 #[inline]
 pub(crate) fn convert_ws_message(message: Option<Message>) -> Result<Option<Event>> {
     Ok(match message {
-        Some(Message::Text(payload)) =>
-            serde_json::from_str(&payload).map(Some).map_err(|why| {
-                warn!("Err deserializing text: {:?}; text: {}", why, payload,);
-
-                why
-            })?,
+        Some(Message::Text(payload)) => serde_json::from_str(&payload).map(Some)?,
         Some(Message::Binary(bytes)) => {
             return Err(Error::UnexpectedBinaryMessage(bytes));
         },