debug, fix panic with zero-duration recording

I had an assert that fired in this case, dating back to when I hadn't plumbed
Result returns through much of .mp4 construction. Now I have, so there's no
excuse in having an assert here. Change to an error return, and tweak it to
not fire in the zero-duration case.

Also fix a problem in the test harness; I hadn't finished converting it for
multi-recording tests, and it was returning the wrong recording.

Because of that, I seem to have stumbled across a related problem in which
asking for zero duration of a non-zero duration recording will return a
recording::Segment with no frames, which will cause panics because its
corresponding .mp4 slices are zero-length. I just adjusted the panic message
here; I'll follow up with changes to address that.

guide/install.md

@@ -171,6 +171,7 @@ been done for you. If not, Create
     Environment=TZ=:/etc/localtime
     Environment=MOONFIRE_FORMAT=google-systemd
     Environment=MOONFIRE_LOG=info
+    Environment=RUST_BACKTRACE=1
     Type=simple
     User=moonfire-nvr
     Nice=-20

prep.sh

@@ -228,6 +228,7 @@ ExecStart=${SERVICE_BIN} run \\
 Environment=TZ=:/etc/localtime
 Environment=MOONFIRE_FORMAT=google-systemd
 Environment=MOONFIRE_LOG=info
+Environment=RUST_BACKTRACE=1
 Type=simple
 User=${NVR_USER}
 Nice=-20

src/db.rs

@@ -646,7 +646,7 @@ impl<'a> Transaction<'a> {
     /// Inserts the specified recording.
     /// The sample file uuid must have been previously reserved. (Although this can be bypassed
     /// for testing; see the `bypass_reservation_for_testing` field.)
-    pub fn insert_recording(&mut self, r: &RecordingToInsert) -> Result<(), Error> {
+    pub fn insert_recording(&mut self, r: &RecordingToInsert) -> Result<i32, Error> {
         self.check_must_rollback()?;
 
         // Sanity checking.
@@ -670,8 +670,9 @@ impl<'a> Transaction<'a> {
         }
         self.must_rollback = true;
         let m = Transaction::get_mods_by_camera(&mut self.mods_by_camera, r.camera_id);
+        let recording_id;
         {
-            let recording_id = m.new_next_recording_id.unwrap_or(cam.next_recording_id);
+            recording_id = m.new_next_recording_id.unwrap_or(cam.next_recording_id);
             let composite_id = composite_id(r.camera_id, recording_id);
             let mut stmt = self.tx.prepare_cached(INSERT_RECORDING_SQL)?;
             stmt.execute_named(&[
@@ -706,7 +707,7 @@ impl<'a> Transaction<'a> {
         m.duration += r.time.end - r.time.start;
         m.sample_file_bytes += r.sample_file_bytes as i64;
         adjust_days(r.time.clone(), 1, &mut m.days);
-        Ok(())
+        Ok(recording_id)
     }
 
     /// Updates the `retain_bytes` for the given camera to the specified limit.

src/mp4.rs

@@ -1083,13 +1083,13 @@ impl FileBuilder {
         for s in &self.segments {
             // The actual range may start before the desired range because it can only start on a
             // key frame. This relationship should hold true:
-            // actual start <= desired start < desired end
+            // actual start <= desired start <= desired end
             let actual_start_90k = s.s.actual_start_90k();
             let skip = s.s.desired_range_90k.start - actual_start_90k;
             let keep = s.s.desired_range_90k.end - s.s.desired_range_90k.start;
-            assert!(skip >= 0 && keep > 0, "segment {}/{}: desired={}..{} actual_start={}",
-                    s.s.camera_id, s.s.recording_id, s.s.desired_range_90k.start,
-                    s.s.desired_range_90k.end, actual_start_90k);
+            if skip < 0 || keep < 0 {
+                return Err(Error::new(format!("skip={} keep={} on segment {:#?}", skip, keep, s)));
+            }
             cur_media_time += skip as u64;
             if unflushed.segment_duration + unflushed.media_time == cur_media_time {
                 unflushed.segment_duration += keep as u64;
@@ -1660,6 +1660,12 @@ mod tests {
             BigEndian::read_u32(&buf[..])
         }
 
+        pub fn get_u64(&self, p: u64) -> u64 {
+            let mut buf = [0u8; 8];
+            self.get(p, &mut buf);
+            BigEndian::read_u64(&buf[..])
+        }
+
         /// Navigates to the next box after the current one, or up if the current one is last.
         pub fn next(&mut self) -> bool {
             let old = self.stack.pop().expect("positioned at root; there is no next");
@@ -2023,6 +2029,30 @@ mod tests {
         assert_eq!(cursor.get_u32(12), 2);
     }
 
+    #[test]
+    fn test_zero_duration_recording() {
+        testutil::init();
+        let db = TestDb::new();
+        let mut encoders = Vec::new();
+        let mut encoder = recording::SampleIndexEncoder::new();
+        encoder.add_sample(2, 1, true);
+        encoder.add_sample(3, 2, false);
+        encoders.push(encoder);
+        let mut encoder = recording::SampleIndexEncoder::new();
+        encoder.add_sample(0, 3, true);
+        encoders.push(encoder);
+
+        // Multi-segment recording with an edit list, encoding with a zero-duration recording.
+        let mp4 = make_mp4_from_encoders(Type::Normal, &db, encoders, 1 .. 2+3);
+        let track = find_track(mp4, 1);
+        let mut cursor = track.edts_cursor.unwrap();
+        cursor.down();
+        cursor.find(b"elst");
+        assert_eq!(cursor.get_u32(4), 1);   // entry_count
+        assert_eq!(cursor.get_u64(8), 4);   // segment_duration
+        assert_eq!(cursor.get_u64(16), 1);  // media_time
+    }
+
     #[test]
     fn test_media_segment() {
         testutil::init();

src/slices.rs

@@ -41,7 +41,7 @@ pub type Body = Box<Stream<Item = Chunk, Error = ::hyper::Error> + Send>;
 
 /// Writes a byte range to the given `io::Write` given a context argument; meant for use with
 /// `Slices`.
-pub trait Slice : Sync + Sized + 'static {
+pub trait Slice : fmt::Debug + Sized + Sync + 'static {
     type Ctx: Send + Clone;
     type Chunk: Send;
 
@@ -70,7 +70,7 @@ pub struct Slices<S> where S: Slice {
     slices: Vec<S>,
 }
 
-impl<S> fmt::Debug for Slices<S> where S: fmt::Debug + Slice {
+impl<S> fmt::Debug for Slices<S> where S: Slice {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
         write!(f, "{} slices with overall length {}:", self.slices.len(), self.len)?;
         let mut start = 0;
@@ -94,7 +94,8 @@ impl<S> Slices<S> where S: Slice {
 
     /// Appends the given slice.
     pub fn append(&mut self, slice: S) {
-        assert!(slice.end() > self.len);
+        assert!(slice.end() > self.len, "end {} <= len {} while adding slice {:?} to slices:\n{:?}",
+                slice.end(), self.len, slice, self);
         self.len = slice.end();
         self.slices.push(slice);
     }
@@ -158,6 +159,7 @@ mod tests {
         range: Range<u64>,
     }
 
+    #[derive(Debug)]
     pub struct FakeSlice {
         end: u64,
         name: &'static str,

src/testutil.rs

@@ -120,11 +120,12 @@ impl TestDb {
         let mut db = self.db.lock();
         let video_sample_entry_id = db.insert_video_sample_entry(
             1920, 1080, [0u8; 100].to_vec(), "avc1.000000".to_owned()).unwrap();
+        let row_id;
         {
             let mut tx = db.tx().unwrap();
             tx.bypass_reservation_for_testing = true;
             const START_TIME: recording::Time = recording::Time(1430006400i64 * TIME_UNITS_PER_SEC);
-            tx.insert_recording(&db::RecordingToInsert{
+            row_id = tx.insert_recording(&db::RecordingToInsert{
                 camera_id: TEST_CAMERA_ID,
                 sample_file_bytes: encoder.sample_file_bytes,
                 time: START_TIME ..
@@ -142,8 +143,7 @@ impl TestDb {
             tx.commit().unwrap();
         }
         let mut row = None;
-        let all_time = recording::Time(i64::min_value()) .. recording::Time(i64::max_value());
-        db.list_recordings_by_time(TEST_CAMERA_ID, all_time,
+        db.list_recordings_by_id(TEST_CAMERA_ID, row_id .. row_id + 1,
                                    |r| { row = Some(r); Ok(()) }).unwrap();
         row.unwrap()
     }