From 48073ddb0a9a6e9c9dd81b04b196230f4372447b Mon Sep 17 00:00:00 2001
From: Carl Hetherington <cth@carlh.net>
Date: Tue, 6 Jan 2015 15:59:57 +0000
Subject: [PATCH] Add some writer-loop debugging from 1.x; ignore out-of-order
 frames when they come from decoders; fix hang if there are unsequenced images
 in the writer queue when we want to stop.

---
 src/lib/video_decoder.cc | 15 ++++++++++++++-
 src/lib/writer.cc        | 33 +++++++++++++++++++++++++++++++++
 2 files changed, 47 insertions(+), 1 deletion(-)

diff --git a/src/lib/video_decoder.cc b/src/lib/video_decoder.cc
index 1bb460da3..8e6f11709 100644
--- a/src/lib/video_decoder.cc
+++ b/src/lib/video_decoder.cc
@@ -21,7 +21,9 @@
 #include "image.h"
 #include "image_proxy.h"
 #include "raw_image_proxy.h"
-#include "content_video.h"
+#include "raw_image_proxy.h"
+#include "film.h"
+#include "log.h"
 
 #include "i18n.h"
 
@@ -280,6 +282,17 @@ VideoDecoder::video (shared_ptr<const ImageProxy> image, VideoFrame frame)
 		to = to_push.front().frame;
 	}
 
+	/* It has been known that this method receives frames out of order; at this
+	   point I'm not sure why, but we'll just ignore them.
+	*/
+
+	if (from && to && from.get() > to.get()) {
+		_video_content->film()->log()->log (
+			String::compose ("Ignoring out-of-order decoded frame %1 after %2", to.get(), from.get()), Log::TYPE_WARNING
+			);
+		return;
+	}
+
 	if (from) {
 		if (_video_content->video_frame_type() == VIDEO_FRAME_TYPE_2D) {
 			fill_2d (from.get(), to.get ());
diff --git a/src/lib/writer.cc b/src/lib/writer.cc
index f844a139a..164b2cd82 100644
--- a/src/lib/writer.cc
+++ b/src/lib/writer.cc
@@ -54,7 +54,10 @@
 #define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
 #define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
 #define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_WARNING);
+#define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_WARNING);
 #define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_DEBUG(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG);
+#define LOG_DEBUG_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_DEBUG);
 
 /* OS X strikes again */
 #undef set_key
@@ -255,6 +258,9 @@ try
 	{
 		boost::mutex::scoped_lock lock (_mutex);
 
+		/* This is for debugging only */
+		bool done_something = false;
+
 		while (true) {
 			
 			if (_finish || _queued_full_in_memory > _maximum_frames_in_memory || have_sequenced_image_at_queue_head ()) {
@@ -272,8 +278,26 @@ try
 			return;
 		}
 
+		/* We stop here if we have been asked to finish, and if either the queue
+		   is empty or we do not have a sequenced image at its head (if this is the
+		   case we will never terminate as no new frames will be sent once
+		   _finish is true).
+		*/
+		if (_finish && (!have_sequenced_image_at_queue_head() || _queue.empty())) {
+			done_something = true;
+			/* (Hopefully temporarily) log anything that was not written */
+			if (!_queue.empty() && !have_sequenced_image_at_queue_head()) {
+				LOG_WARNING (N_("Finishing writer with a left-over queue of %1:"), _queue.size());
+				for (list<QueueItem>::const_iterator i = _queue.begin(); i != _queue.end(); ++i) {
+					LOG_WARNING (N_("- type %1, size %2, frame %3, eyes %4"), i->type, i->size, i->frame, i->eyes);
+				}
+				LOG_WARNING (N_("Last written frame %1, last written eyes %2"), _last_written_frame, _last_written_eyes);
+			}
+			return;
+		}
 		/* Write any frames that we can write; i.e. those that are in sequence. */
 		while (have_sequenced_image_at_queue_head ()) {
+			done_something = true;
 			QueueItem qi = _queue.front ();
 			_queue.pop_front ();
 			if (qi.type == QueueItem::FULL && qi.encoded) {
@@ -322,6 +346,7 @@ try
 		}
 
 		while (_queued_full_in_memory > _maximum_frames_in_memory) {
+			done_something = true;
 			/* Too many frames in memory which can't yet be written to the stream.
 			   Write some FULL frames to disk.
 			*/
@@ -352,6 +377,14 @@ try
 			--_queued_full_in_memory;
 		}
 
+		if (!done_something) {
+			LOG_DEBUG_NC ("Writer loop ran without doing anything");
+			LOG_DEBUG ("_queued_full_in_memory=%1", _queued_full_in_memory);
+			LOG_DEBUG ("_queue_size=%1", _queue.size ());
+			LOG_DEBUG ("_finish=%1", _finish);
+			LOG_DEBUG ("_last_written_frame=%1", _last_written_frame);
+		}
+
 		/* The queue has probably just gone down a bit; notify anything wait()ing on _full_condition */
 		_full_condition.notify_all ();
 	}
-- 
2.30.2