logging improvements

*   allow debug/trace logging on release builds again
*   enable log messages from hyper. I didn't notice they went
    away with 0.14.0, although there's a breaking change in the log:
    https://github.com/hyperium/hyper/blob/master/CHANGELOG.md#v0140-2020-12-23
*   downgrade some particularly spammy messages

server/Cargo.lock

@@ -1273,6 +1273,7 @@ dependencies = [
  "tokio",
  "tokio-stream",
  "tokio-tungstenite",
+ "tracing",
  "url",
  "uuid",
 ]
@@ -2356,10 +2357,23 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "09adeb8c97449311ccd28a427f96fb563e7fd31aabf994189879d9da2394b89d"
 dependencies = [
  "cfg-if 1.0.0",
+ "log",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-attributes"
+version = "0.1.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c42e6fa53307c8a17e4ccd4dc81cf5ec38db9209f59b222210375b54ee40d1e2"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.18"

server/Cargo.toml

@@ -39,7 +39,7 @@ http-serve = { version = "0.3.1", features = ["dir"] }
 hyper = { version = "0.14.2", features = ["http1", "server", "stream", "tcp"] }
 lazy_static = "1.0"
 libc = "0.2"
-log = { version = "0.4", features = ["release_max_level_info"] }
+log = { version = "0.4" }
 memchr = "2.0.2"
 moonfire-tflite = { git = "https://github.com/scottlamb/moonfire-tflite", features = ["edgetpu"], optional = true }
 mylog = { git = "https://github.com/scottlamb/mylog" }
@@ -59,6 +59,7 @@ time = "0.1"
 tokio = { version = "1.0", features = ["macros", "parking_lot", "rt-multi-thread", "signal", "time"] }
 tokio-stream = "0.1.5"
 tokio-tungstenite = "0.14.0"
+tracing = { version = "0.1", features = ["log"] }
 url = "2.1.1"
 uuid = { version = "0.8", features = ["serde", "std", "v4"] }
 

server/src/mp4.rs

@@ -1111,8 +1111,8 @@ impl FileBuilder {
                 self.body.buf.len()
             );
         }
-        debug!("segments: {:#?}", self.segments);
-        debug!("slices: {:?}", self.body.slices);
+        trace!("segments: {:#?}", self.segments);
+        trace!("slices: {:?}", self.body.slices);
         let last_modified =
             ::std::time::UNIX_EPOCH + ::std::time::Duration::from_secs(max_end as u64);
         let etag = etag.finalize();
@@ -1410,7 +1410,7 @@ impl FileBuilder {
 
         flushed.push(unflushed);
 
-        debug!("Using edit list: {:?}", flushed);
+        trace!("Using edit list: {:?}", flushed);
         write_length!(self, {
             self.body.buf.extend_from_slice(b"edts");
             write_length!(self, {

server/src/stream.rs

@@ -6,7 +6,7 @@ use crate::h264;
 use cstr::cstr;
 use failure::{bail, Error};
 use lazy_static::lazy_static;
-use log::{debug, warn};
+use log::warn;
 use std::convert::TryFrom;
 use std::ffi::CString;
 use std::result::Result;
@@ -117,7 +117,6 @@ impl Opener<FfmpegStream> for Ffmpeg {
             let s = input.streams();
             for i in 0..s.len() {
                 if s.get(i).codecpar().codec_type().is_video() {
-                    debug!("Video stream index is {}", i);
                     video_i = Some(i);
                     break;
                 }

server/src/streamer.rs

@@ -135,10 +135,6 @@ where
             let _t = TimerGuard::new(&clocks, || "inserting video sample entry");
             self.db.lock().insert_video_sample_entry(extra_data.entry)?
         };
-        debug!(
-            "{}: video_sample_entry_id={}",
-            self.short_name, video_sample_entry_id
-        );
         let mut seen_key_frame = false;
 
         // Seconds since epoch at which to next rotate.

server/src/web.rs

@@ -19,7 +19,7 @@ use http::header::{self, HeaderValue};
 use http::{status::StatusCode, Request, Response};
 use http_serve::dir::FsDir;
 use hyper::body::Bytes;
-use log::{debug, info, warn};
+use log::{debug, info, trace, warn};
 use memchr::memchr;
 use nom::bytes::complete::{tag, take_while1};
 use nom::combinator::{all_consuming, map, map_res, opt};
@@ -836,7 +836,7 @@ impl Service {
                                 format!("invalid s parameter: {}", value),
                             )
                         })?;
-                        debug!("stream_view_mp4: appending s={:?}", s);
+                        trace!("stream_view_mp4: appending s={:?}", s);
                         let mut est_segments = usize::try_from(s.ids.end - s.ids.start).unwrap();
                         if let Some(end) = s.end_time {
                             // There should be roughly ceil((end - start) /
@@ -887,10 +887,12 @@ impl Service {
                                 let start = cmp::max(0, s.start_time - cur_off);
                                 let end = cmp::min(wd, end_time - cur_off);
                                 let wr = i32::try_from(start).unwrap()..i32::try_from(end).unwrap();
-                                debug!(
+                                trace!(
                                     "...appending recording {} with wall duration {:?} \
                                        (out of total {})",
-                                    r.id, wr, wd
+                                    r.id,
+                                    wr,
+                                    wd
                                 );
                                 if start_time_for_filename.is_none() {
                                     start_time_for_filename =
@@ -906,7 +908,7 @@ impl Service {
                                         );
                                 builder.append(&db, r, mr, true)?;
                             } else {
-                                debug!("...skipping recording {} wall dur {}", r.id, wd);
+                                trace!("...skipping recording {} wall dur {}", r.id, wd);
                             }
                             cur_off += wd;
                             Ok(())