Add a bit more debug logging to the player.

6 files changed, 12 insertions, 1 deletions

diff --git a/src/lib/dcpomatic_log.h b/src/lib/dcpomatic_log.h
index c969c508d..52a77f2f1 100644
--- a/src/lib/dcpomatic_log.h
+++ b/src/lib/dcpomatic_log.h
@@ -38,3 +38,5 @@ extern boost::shared_ptr<Log> dcpomatic_log;
 #define LOG_DEBUG_THREED_NC(...) dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DEBUG_THREED);
 #define LOG_DISK(...)         dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DISK);
 #define LOG_DISK_NC(...)      dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DISK);
+#define LOG_DEBUG_PLAYER(...)    dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DEBUG_PLAYER);
+#define LOG_DEBUG_PLAYER_NC(...) dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DEBUG_PLAYER);
diff --git a/src/lib/log_entry.cc b/src/lib/log_entry.cc
index 01d1415c7..f890d488a 100644
--- a/src/lib/log_entry.cc
+++ b/src/lib/log_entry.cc
@@ -33,6 +33,7 @@ int const LogEntry::TYPE_TIMING       = 0x020;
 int const LogEntry::TYPE_DEBUG_EMAIL  = 0x040;
 int const LogEntry::TYPE_DEBUG_VIDEO_VIEW = 0x080;
 int const LogEntry::TYPE_DISK         = 0x100;
+int const LogEntry::TYPE_DEBUG_PLAYER = 0x200;
 
 using std::string;
 
diff --git a/src/lib/log_entry.h b/src/lib/log_entry.h
index 136ab00f9..4bace41a4 100644
--- a/src/lib/log_entry.h
+++ b/src/lib/log_entry.h
@@ -37,6 +37,7 @@ public:
 	static const int TYPE_DEBUG_EMAIL;
 	static const int TYPE_DEBUG_VIDEO_VIEW; ///< real-time video viewing (i.e. "playback")
 	static const int TYPE_DISK;
+	static const int TYPE_DEBUG_PLAYER;     ///< the Player class
 
 	explicit LogEntry (int type);
 	virtual ~LogEntry () {}
diff --git a/src/lib/player.cc b/src/lib/player.cc
index 4f81199a5..d2e5ed521 100644
--- a/src/lib/player.cc
+++ b/src/lib/player.cc
@@ -23,6 +23,7 @@
 #include "audio_buffers.h"
 #include "content_audio.h"
 #include "dcp_content.h"
+#include "dcpomatic_log.h"
 #include "job.h"
 #include "image.h"
 #include "raw_image_proxy.h"
@@ -664,6 +665,7 @@ Player::pass ()
 		break;
 	}
 	case BLACK:
+		LOG_DEBUG_PLAYER ("Emit black for gap at %1", to_string(_black.position()));
 		emit_video (black_player_video_frame(EYES_BOTH), _black.position());
 		_black.set_position (_black.position() + one_video_frame());
 		break;
@@ -836,10 +838,12 @@ Player::video (weak_ptr<Piece> wp, ContentVideo video)
 				}
 				while (j < fill_to || eyes != fill_to_eyes) {
 					if (last != _last_video.end()) {
+						LOG_DEBUG_PLAYER("Fill using last video at %1 in 3D mode", to_string(j));
 						shared_ptr<PlayerVideo> copy = last->second->shallow_copy();
 						copy->set_eyes (eyes);
 						emit_video (copy, j);
 					} else {
+						LOG_DEBUG_PLAYER("Fill using black at %1 in 3D mode", to_string(j));
 						emit_video (black_player_video_frame(eyes), j);
 					}
 					if (eyes == EYES_RIGHT) {
diff --git a/src/lib/shuffler.cc b/src/lib/shuffler.cc
index 2d6465526..d913f48ef 100644
--- a/src/lib/shuffler.cc
+++ b/src/lib/shuffler.cc
@@ -116,6 +116,7 @@ void
 Shuffler::flush ()
 {
 	BOOST_FOREACH (Store i, _store) {
+		LOG_DEBUG_PLAYER("Flushing %1 from shuffler", i.second.frame);
 		Video (i.first, i.second);
 	}
 }
diff --git a/test/test.cc b/test/test.cc
index 3ec78e68b..90decc2df 100644
--- a/test/test.cc
+++ b/test/test.cc
@@ -87,7 +87,9 @@ setup_test_config ()
 	Config::instance()->set_default_j2k_bandwidth (100000000);
 	Config::instance()->set_default_interop (false);
 	Config::instance()->set_default_still_length (10);
-	Config::instance()->set_log_types (LogEntry::TYPE_GENERAL | LogEntry::TYPE_WARNING | LogEntry::TYPE_ERROR | LogEntry::TYPE_DEBUG_THREED | LogEntry::TYPE_DEBUG_ENCODE);
+	Config::instance()->set_log_types (
+		LogEntry::TYPE_GENERAL | LogEntry::TYPE_WARNING | LogEntry::TYPE_ERROR | LogEntry::TYPE_DEBUG_THREED | LogEntry::TYPE_DEBUG_ENCODE | LogEntry::TYPE_DEBUG_PLAYER
+		);
 	Config::instance()->set_automatic_audio_analysis (false);
 }