Merge master.

29 files changed, 272 insertions, 180 deletions

diff --git a/src/lib/config.cc b/src/lib/config.cc
index 754346418..8be31a329 100644
--- a/src/lib/config.cc
+++ b/src/lib/config.cc
@@ -73,6 +73,7 @@ Config::Config ()
 	, _check_for_updates (false)
 	, _check_for_test_updates (false)
 	, _maximum_j2k_bandwidth (250000000)
+	, _log_types (Log::TYPE_GENERAL | Log::TYPE_WARNING | Log::TYPE_ERROR)
 {
 	_allowed_dcp_frame_rates.push_back (24);
 	_allowed_dcp_frame_rates.push_back (25);
@@ -189,6 +190,8 @@ Config::read ()
 
 	_maximum_j2k_bandwidth = f.optional_number_child<int> ("MaximumJ2KBandwidth").get_value_or (250000000);
 	_allow_any_dcp_frame_rate = f.optional_bool_child ("AllowAnyDCPFrameRate");
+
+	_log_types = f.optional_number_child<int> ("LogTypes").get_value_or (Log::TYPE_GENERAL | Log::TYPE_WARNING | Log::TYPE_ERROR);
 }
 
 void
@@ -366,6 +369,7 @@ Config::write () const
 
 	root->add_child("MaximumJ2KBandwidth")->add_child_text (raw_convert<string> (_maximum_j2k_bandwidth));
 	root->add_child("AllowAnyDCPFrameRate")->add_child_text (_allow_any_dcp_frame_rate ? "1" : "0");
+	root->add_child("LogTypes")->add_child_text (raw_convert<string> (_log_types));
 	
 	doc.write_to_file_formatted (file(false).string ());
 }
diff --git a/src/lib/config.h b/src/lib/config.h
index ffaacf8f1..ccd37ec1e 100644
--- a/src/lib/config.h
+++ b/src/lib/config.h
@@ -188,6 +188,10 @@ public:
 	int maximum_j2k_bandwidth () const {
 		return _maximum_j2k_bandwidth;
 	}
+
+	int log_types () const {
+		return _log_types;
+	}
 	
 	/** @param n New number of local encoding threads */
 	void set_num_local_encoding_threads (int n) {
@@ -339,6 +343,11 @@ public:
 		_maximum_j2k_bandwidth = b;
 		changed ();
 	}
+
+	void set_log_types (int t) {
+		_log_types = t;
+		changed ();
+	}
 	
 	boost::filesystem::path signer_chain_directory () const;
 
@@ -401,6 +410,7 @@ private:
 	bool _check_for_test_updates;
 	/** maximum allowed J2K bandwidth in bits per second */
 	int _maximum_j2k_bandwidth;
+	int _log_types;
 
 	/** Singleton instance, or 0 */
 	static Config* _instance;
diff --git a/src/lib/content.h b/src/lib/content.h
index 1d3764c20..6bbf33b35 100644
--- a/src/lib/content.h
+++ b/src/lib/content.h
@@ -138,6 +138,10 @@ public:
 		_change_signals_frequent = f;
 	}
 
+	boost::shared_ptr<const Film> film () const {
+		return _film.lock ();
+	}
+
 	boost::signals2::signal<void (boost::weak_ptr<Content>, int, bool)> Changed;
 
 protected:
diff --git a/src/lib/cross.cc b/src/lib/cross.cc
index eadbd75d8..53ef5723a 100644
--- a/src/lib/cross.cc
+++ b/src/lib/cross.cc
@@ -44,6 +44,12 @@
 #endif
 #include "exceptions.h"
 
+#include "i18n.h"
+
+#define LOG_GENERAL(...) log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_ERROR(...) log->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_ERROR_NC(...) log->log (__VA_ARGS__, Log::TYPE_ERROR);
+
 using std::pair;
 using std::list;
 using std::ifstream;
@@ -157,7 +163,7 @@ run_ffprobe (boost::filesystem::path content, boost::filesystem::path out, share
 	HANDLE child_stderr_read;
 	HANDLE child_stderr_write;
 	if (!CreatePipe (&child_stderr_read, &child_stderr_write, &security, 0)) {
-		log->log ("ffprobe call failed (could not CreatePipe)");
+		LOG_ERROR_NC ("ffprobe call failed (could not CreatePipe)");
 		return;
 	}
 
@@ -184,13 +190,13 @@ run_ffprobe (boost::filesystem::path content, boost::filesystem::path out, share
 	PROCESS_INFORMATION process_info;
 	ZeroMemory (&process_info, sizeof (process_info));
 	if (!CreateProcess (0, command, 0, 0, TRUE, CREATE_NO_WINDOW, 0, 0, &startup_info, &process_info)) {
-		log->log ("ffprobe call failed (could not CreateProcess)");
+		LOG_ERROR_NC (N_("ffprobe call failed (could not CreateProcess)"));
 		return;
 	}
 
 	FILE* o = fopen_boost (out, "w");
 	if (!o) {
-		log->log ("ffprobe call failed (could not create output file)");
+		LOG_ERROR_NC (N_("ffprobe call failed (could not create output file)"));
 		return;
 	}
 
@@ -215,7 +221,7 @@ run_ffprobe (boost::filesystem::path content, boost::filesystem::path out, share
 
 #ifdef DCPOMATIC_LINUX 
 	string ffprobe = "ffprobe \"" + content.string() + "\" 2> \"" + out.string() + "\"";
-	log->log (String::compose ("Probing with %1", ffprobe));
+	LOG_GENERAL (N_("Probing with %1"), ffprobe);
         system (ffprobe.c_str ());
 #endif
 
@@ -225,7 +231,7 @@ run_ffprobe (boost::filesystem::path content, boost::filesystem::path out, share
 	path /= "ffprobe";
 	
 	string ffprobe = path.string() + " \"" + content.string() + "\" 2> \"" + out.string() + "\"";
-	log->log (String::compose ("Probing with %1", ffprobe));
+	LOG_GENERAL (N_("Probing with %1"), ffprobe);
 	system (ffprobe.c_str ());
 #endif
 }
diff --git a/src/lib/dcp_video_frame.cc b/src/lib/dcp_video_frame.cc
index d154ba96b..1aae64ac7 100644
--- a/src/lib/dcp_video_frame.cc
+++ b/src/lib/dcp_video_frame.cc
@@ -62,6 +62,8 @@
 #include "cross.h"
 #include "player_video_frame.h"
 
+#define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+
 #include "i18n.h"
 
 using std::string;
@@ -247,13 +249,13 @@ DCPVideoFrame::encode_locally ()
 
 	switch (_frame->eyes()) {
 	case EYES_BOTH:
-		_log->log (String::compose (N_("Finished locally-encoded frame %1 for mono"), _index));
+		LOG_GENERAL (N_("Finished locally-encoded frame %1 for mono"), _index);
 		break;
 	case EYES_LEFT:
-		_log->log (String::compose (N_("Finished locally-encoded frame %1 for L"), _index));
+		LOG_GENERAL (N_("Finished locally-encoded frame %1 for L"), _index);
 		break;
 	case EYES_RIGHT:
-		_log->log (String::compose (N_("Finished locally-encoded frame %1 for R"), _index));
+		LOG_GENERAL (N_("Finished locally-encoded frame %1 for R"), _index);
 		break;
 	default:
 		break;
@@ -290,7 +292,7 @@ DCPVideoFrame::encode_remotely (ServerDescription serv)
 	root->add_child("Version")->add_child_text (raw_convert<string> (SERVER_LINK_VERSION));
 	add_metadata (root);
 
-	_log->log (String::compose (N_("Sending frame %1 to remote"), _index));
+	LOG_GENERAL (N_("Sending frame %1 to remote"), _index);
 	
 	/* Send XML metadata */
 	stringstream xml;
@@ -307,7 +309,7 @@ DCPVideoFrame::encode_remotely (ServerDescription serv)
 	shared_ptr<EncodedData> e (new RemotelyEncodedData (socket->read_uint32 ()));
 	socket->read (e->data(), e->size());
 
-	_log->log (String::compose (N_("Finished remotely-encoded frame %1"), _index));
+	LOG_GENERAL (N_("Finished remotely-encoded frame %1"), _index);
 	
 	return e;
 }
diff --git a/src/lib/decoder.h b/src/lib/decoder.h
index 0ec73ba91..18f612e53 100644
--- a/src/lib/decoder.h
+++ b/src/lib/decoder.h
@@ -31,7 +31,6 @@
 #include "dcpomatic_time.h"
 
 class Decoded;
-class Film;
 
 /** @class Decoder.
  *  @brief Parent class for decoders of content.
diff --git a/src/lib/encoder.cc b/src/lib/encoder.cc
index 2364b67a7..5dc9e47c7 100644
--- a/src/lib/encoder.cc
+++ b/src/lib/encoder.cc
@@ -39,6 +39,10 @@
 
 #include "i18n.h"
 
+#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
+
 using std::pair;
 using std::string;
 using std::stringstream;
@@ -76,7 +80,7 @@ Encoder::~Encoder ()
 void
 Encoder::add_worker_threads (ServerDescription d)
 {
-	_film->log()->log (String::compose (N_("Adding %1 worker threads for remote %2"), d.host_name ()));
+	LOG_GENERAL (N_("Adding %1 worker threads for remote %2"), d.host_name ());
 	for (int i = 0; i < d.threads(); ++i) {
 		_threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, d)));
 	}
@@ -98,11 +102,10 @@ Encoder::process_end ()
 {
 	boost::mutex::scoped_lock lock (_mutex);
 
-	_film->log()->log (String::compose (N_("Clearing queue of %1"), _queue.size ()));
+	LOG_GENERAL (N_("Clearing queue of %1"), _queue.size ());
 
 	/* Keep waking workers until the queue is empty */
 	while (!_queue.empty ()) {
-		_film->log()->log (String::compose (N_("Waking with %1"), _queue.size ()), Log::VERBOSE);
 		_condition.notify_all ();
 		_condition.wait (lock);
 	}
@@ -111,7 +114,7 @@ Encoder::process_end ()
 	
 	terminate_threads ();
 
-	_film->log()->log (String::compose (N_("Mopping up %1"), _queue.size()));
+	LOG_GENERAL (N_("Mopping up %1"), _queue.size());
 
 	/* The following sequence of events can occur in the above code:
 	     1. a remote worker takes the last image off the queue
@@ -123,12 +126,12 @@ Encoder::process_end ()
 	*/
 
 	for (list<shared_ptr<DCPVideoFrame> >::iterator i = _queue.begin(); i != _queue.end(); ++i) {
-		_film->log()->log (String::compose (N_("Encode left-over frame %1"), (*i)->index ()));
+		LOG_GENERAL (N_("Encode left-over frame %1"), (*i)->index ());
 		try {
 			_writer->write ((*i)->encode_locally(), (*i)->index (), (*i)->eyes ());
 			frame_done ();
 		} catch (std::exception& e) {
-			_film->log()->log (String::compose (N_("Local encode failed (%1)"), e.what ()));
+			LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
 		}
 	}
 		
@@ -188,9 +191,9 @@ Encoder::process_video (shared_ptr<PlayerVideoFrame> pvf)
 
 	/* Wait until the queue has gone down a bit */
 	while (_queue.size() >= _threads.size() * 2 && !_terminate) {
-		TIMING ("decoder sleeps with queue of %1", _queue.size());
+		LOG_TIMING ("decoder sleeps with queue of %1", _queue.size());
 		_condition.wait (lock);
-		TIMING ("decoder wakes with queue of %1", _queue.size());
+		LOG_TIMING ("decoder wakes with queue of %1", _queue.size());
 	}
 
 	if (_terminate) {
@@ -209,7 +212,7 @@ Encoder::process_video (shared_ptr<PlayerVideoFrame> pvf)
 		frame_done ();
 	} else {
 		/* Queue this new frame for encoding */
-		TIMING ("adding to queue of %1", _queue.size ());
+		LOG_TIMING ("adding to queue of %1", _queue.size ());
 		_queue.push_back (shared_ptr<DCPVideoFrame> (
 					  new DCPVideoFrame (
 						  pvf,
@@ -266,7 +269,7 @@ try
 	
 	while (1) {
 
-		TIMING ("encoder thread %1 sleeps", boost::this_thread::get_id());
+		LOG_TIMING ("[%1] encoder thread sleeps", boost::this_thread::get_id());
 		boost::mutex::scoped_lock lock (_mutex);
 		while (_queue.empty () && !_terminate) {
 			_condition.wait (lock);
@@ -276,9 +279,9 @@ try
 			return;
 		}
 
-		TIMING ("encoder thread %1 wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
+		LOG_TIMING ("[%1] encoder thread wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
 		shared_ptr<DCPVideoFrame> vf = _queue.front ();
-		TIMING ("encoder thread %1 pops frame %2 (%3) from queue", boost::this_thread::get_id(), vf->index(), vf->eyes ());
+		LOG_TIMING ("[%1] encoder thread pops frame %2 (%3) from queue", boost::this_thread::get_id(), vf->index(), vf->eyes ());
 		_queue.pop_front ();
 		
 		lock.unlock ();
@@ -290,7 +293,7 @@ try
 				encoded = vf->encode_remotely (server.get ());
 
 				if (remote_backoff > 0) {
-					_film->log()->log (String::compose (N_("%1 was lost, but now she is found; removing backoff"), server->host_name ()));
+					LOG_GENERAL ("%1 was lost, but now she is found; removing backoff", server->host_name ());
 				}
 				
 				/* This job succeeded, so remove any backoff */
@@ -301,20 +304,19 @@ try
 					/* back off more */
 					remote_backoff += 10;
 				}
-				_film->log()->log (
-					String::compose (
-						N_("Remote encode of %1 on %2 failed (%3); thread sleeping for %4s"),
-						vf->index(), server->host_name(), e.what(), remote_backoff)
+				LOG_ERROR (
+					N_("Remote encode of %1 on %2 failed (%3); thread sleeping for %4s"),
+					vf->index(), server->host_name(), e.what(), remote_backoff
 					);
 			}
 				
 		} else {
 			try {
-				TIMING ("encoder thread %1 begins local encode of %2", boost::this_thread::get_id(), vf->index());
+				LOG_TIMING ("[%1] encoder thread begins local encode of %2", boost::this_thread::get_id(), vf->index());
 				encoded = vf->encode_locally ();
-				TIMING ("encoder thread %1 finishes local encode of %2", boost::this_thread::get_id(), vf->index());
+				LOG_TIMING ("[%1] encoder thread finishes local encode of %2", boost::this_thread::get_id(), vf->index());
 			} catch (std::exception& e) {
-				_film->log()->log (String::compose (N_("Local encode failed (%1)"), e.what ()));
+				LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
 			}
 		}
 
@@ -323,9 +325,7 @@ try
 			frame_done ();
 		} else {
 			lock.lock ();
-			_film->log()->log (
-				String::compose (N_("Encoder thread %1 pushes frame %2 back onto queue after failure"), boost::this_thread::get_id(), vf->index())
-				);
+			LOG_GENERAL (N_("[%1] Encoder thread pushes frame %2 back onto queue after failure"), boost::this_thread::get_id(), vf->index());
 			_queue.push_front (vf);
 			lock.unlock ();
 		}
diff --git a/src/lib/ffmpeg_content.cc b/src/lib/ffmpeg_content.cc
index 2b507ab37..9889d511c 100644
--- a/src/lib/ffmpeg_content.cc
+++ b/src/lib/ffmpeg_content.cc
@@ -36,6 +36,8 @@ extern "C" {
 
 #include "i18n.h"
 
+#define LOG_GENERAL(...) film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+
 using std::string;
 using std::stringstream;
 using std::vector;
@@ -173,7 +175,7 @@ FFmpegContent::examine (shared_ptr<Job> job)
 
 	shared_ptr<const Film> film = _film.lock ();
 	assert (film);
-	film->log()->log (String::compose ("Video length obtained from header as %1 frames", video_length.frames (video_frame_rate ())));
+	LOG_GENERAL ("Video length obtained from header as %1 frames", video_length.frames (video_frame_rate ()));
 
 	{
 		boost::mutex::scoped_lock lm (_mutex);
diff --git a/src/lib/ffmpeg_decoder.cc b/src/lib/ffmpeg_decoder.cc
index d668deb6f..0dae2a4ed 100644
--- a/src/lib/ffmpeg_decoder.cc
+++ b/src/lib/ffmpeg_decoder.cc
@@ -44,9 +44,14 @@ extern "C" {
 #include "audio_buffers.h"
 #include "ffmpeg_content.h"
 #include "image_proxy.h"
+#include "film.h"
 
 #include "i18n.h"
 
+#define LOG_GENERAL(...) _video_content->film()->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_ERROR(...) _video_content->film()->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_WARNING(...) _video_content->film()->log()->log (__VA_ARGS__, Log::TYPE_WARNING);
+
 using std::cout;
 using std::string;
 using std::vector;
@@ -138,7 +143,7 @@ FFmpegDecoder::pass ()
 			/* Maybe we should fail here, but for now we'll just finish off instead */
 			char buf[256];
 			av_strerror (r, buf, sizeof(buf));
-			_log->log (String::compose (N_("error on av_read_frame (%1) (%2)"), buf, r));
+			LOG_ERROR (N_("error on av_read_frame (%1) (%2)"), buf, r);
 		}
 
 		flush ();
@@ -431,7 +436,7 @@ FFmpegDecoder::decode_audio_packet ()
 		int const decode_result = avcodec_decode_audio4 (audio_codec_context(), _frame, &frame_finished, &copy_packet);
 
 		if (decode_result < 0) {
-			_log->log (String::compose ("avcodec_decode_audio4 failed (%1)", decode_result));
+			LOG_ERROR ("avcodec_decode_audio4 failed (%1)", decode_result);
 			return;
 		}
 
@@ -473,7 +478,7 @@ FFmpegDecoder::decode_video_packet ()
 	if (i == _filter_graphs.end ()) {
 		graph.reset (new FilterGraph (_ffmpeg_content, dcp::Size (_frame->width, _frame->height), (AVPixelFormat) _frame->format));
 		_filter_graphs.push_back (graph);
-		_log->log (String::compose (N_("New graph for %1x%2, pixel format %3"), _frame->width, _frame->height, _frame->format));
+		LOG_GENERAL (N_("New graph for %1x%2, pixel format %3"), _frame->width, _frame->height, _frame->format);
 	} else {
 		graph = *i;
 	}
@@ -486,9 +491,12 @@ FFmpegDecoder::decode_video_packet ()
 		
 		if (i->second != AV_NOPTS_VALUE) {
 			double const pts = i->second * av_q2d (_format_context->streams[_video_stream]->time_base) + _pts_offset.seconds ();
-			video (shared_ptr<ImageProxy> (new RawImageProxy (image)), rint (pts * _ffmpeg_content->video_frame_rate ()));
+			video (
+				shared_ptr<ImageProxy> (new RawImageProxy (image, _video_content->film()->log())),
+				rint (pts * _ffmpeg_content->video_frame_rate ())
+				);
 		} else {
-			_log->log ("Dropping frame without PTS");
+			LOG_WARNING ("Dropping frame without PTS");
 		}
 	}
 
diff --git a/src/lib/ffmpeg_examiner.cc b/src/lib/ffmpeg_examiner.cc
index df12830f8..d9bcedfc5 100644
--- a/src/lib/ffmpeg_examiner.cc
+++ b/src/lib/ffmpeg_examiner.cc
@@ -176,7 +176,7 @@ FFmpegExaminer::video_size () const
 ContentTime
 FFmpegExaminer::video_length () const
 {
-	ContentTime const length = ContentTime::from_seconds (double (_format_context->duration) / AV_TIME_BASE);
+	ContentTime const length = ContentTime::from_seconds (double (_format_context->duration - _format_context->start_time) / AV_TIME_BASE);
 	return ContentTime (max (int64_t (1), length.get ()));
 }
 
diff --git a/src/lib/film.cc b/src/lib/film.cc
index 50b1b4fad..25730ae1c 100644
--- a/src/lib/film.cc
+++ b/src/lib/film.cc
@@ -81,6 +81,9 @@ using dcp::Size;
 using dcp::Signer;
 using dcp::raw_convert;
 
+#define LOG_GENERAL(...) log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_GENERAL_NC(...) log()->log (__VA_ARGS__, Log::TYPE_GENERAL);
+
 /* 5 -> 6
  * AudioMapping XML changed.
  * 6 -> 7
@@ -256,43 +259,43 @@ Film::make_dcp ()
 	 */
 	write_metadata ();
 
-	log()->log (String::compose ("DCP-o-matic %1 git %2 using %3", dcpomatic_version, dcpomatic_git_commit, dependency_version_summary()));
+	LOG_GENERAL ("DCP-o-matic %1 git %2 using %3", dcpomatic_version, dcpomatic_git_commit, dependency_version_summary());
 
 	{
 		char buffer[128];
 		gethostname (buffer, sizeof (buffer));
-		log()->log (String::compose ("Starting to make DCP on %1", buffer));
+		LOG_GENERAL ("Starting to make DCP on %1", buffer);
 	}
 
 	ContentList cl = content ();
 	for (ContentList::const_iterator i = cl.begin(); i != cl.end(); ++i) {
-		log()->log (String::compose ("Content: %1", (*i)->technical_summary()));
+		LOG_GENERAL ("Content: %1", (*i)->technical_summary());
 	}
-	log()->log (String::compose ("DCP video rate %1 fps", video_frame_rate()));
-	log()->log (String::compose ("%1 threads", Config::instance()->num_local_encoding_threads()));
-	log()->log (String::compose ("J2K bandwidth %1", j2k_bandwidth()));
+	LOG_GENERAL ("DCP video rate %1 fps", video_frame_rate());
+	LOG_GENERAL ("%1 threads", Config::instance()->num_local_encoding_threads());
+	LOG_GENERAL ("J2K bandwidth %1", j2k_bandwidth());
 #ifdef DCPOMATIC_DEBUG
-	log()->log ("DCP-o-matic built in debug mode.");
+	LOG_GENERAL_NC ("DCP-o-matic built in debug mode.");
 #else
-	log()->log ("DCP-o-matic built in optimised mode.");
+	LOG_GENERAL_NC ("DCP-o-matic built in optimised mode.");
 #endif
 #ifdef LIBDCP_DEBUG
-	log()->log ("libdcp built in debug mode.");
+	LOG_GENERAL_NC ("libdcp built in debug mode.");
 #else
-	log()->log ("libdcp built in optimised mode.");
+	LOG_GENERAL_NC ("libdcp built in optimised mode.");
 #endif
 
 #ifdef DCPOMATIC_WINDOWS
 	OSVERSIONINFO info;
 	info.dwOSVersionInfoSize = sizeof (info);
 	GetVersionEx (&info);
-	log()->log (String::compose ("Windows version %1.%2.%3 SP %4", info.dwMajorVersion, info.dwMinorVersion, info.dwBuildNumber, info.szCSDVersion));
+	LOG_GENERAL ("Windows version %1.%2.%3 SP %4", info.dwMajorVersion, info.dwMinorVersion, info.dwBuildNumber, info.szCSDVersion);
 #endif	
 	
-	log()->log (String::compose ("CPU: %1, %2 processors", cpu_info(), boost::thread::hardware_concurrency ()));
+	LOG_GENERAL ("CPU: %1, %2 processors", cpu_info(), boost::thread::hardware_concurrency ());
 	list<pair<string, string> > const m = mount_info ();
 	for (list<pair<string, string> >::const_iterator i = m.begin(); i != m.end(); ++i) {
-		log()->log (String::compose ("Mount: %1 %2", i->first, i->second));
+		LOG_GENERAL ("Mount: %1 %2", i->first, i->second);
 	}
 	
 	if (container() == 0) {
@@ -766,11 +769,11 @@ Film::j2c_path (int f, Eyes e, bool t) const
 	return file (p);
 }
 
-/** @return List of subdirectories (not full paths) containing DCPs that can be successfully dcp::DCP::read() */
-list<boost::filesystem::path>
-Film::dcps () const
+/** Find all the DCPs in our directory that can be libdcp::DCP::read() and return details of their CPLs */
+vector<CPLSummary>
+Film::cpls () const
 {
-	list<boost::filesystem::path> out;
+	vector<CPLSummary> out;
 	
 	boost::filesystem::path const dir = directory ();
 	for (boost::filesystem::directory_iterator i = boost::filesystem::directory_iterator(dir); i != boost::filesystem::directory_iterator(); ++i) {
@@ -782,7 +785,14 @@ Film::dcps () const
 			try {
 				dcp::DCP dcp (*i);
 				dcp.read ();
-				out.push_back (i->path().leaf ());
+				out.push_back (
+					CPLSummary (
+						i->path().leaf().string(),
+						dcp.cpls().front()->id(),
+						dcp.cpls().front()->annotation_text(),
+						dcp.cpls().front()->file()
+						)
+					);
 			} catch (...) {
 
 			}
@@ -961,26 +971,15 @@ Film::frame_size () const
 dcp::EncryptedKDM
 Film::make_kdm (
 	shared_ptr<dcp::Certificate> target,
-	boost::filesystem::path dcp_dir,
+	boost::filesystem::path cpl_file,
 	dcp::LocalTime from,
 	dcp::LocalTime until
 	) const
 {
-	shared_ptr<const Signer> signer = make_signer ();
-
-	dcp::DCP dcp (dir (dcp_dir.string ()));
-	
-	try {
-		dcp.read ();
-	} catch (...) {
-		throw KDMError (_("Could not read DCP to make KDM for"));
-	}
-	
-	dcp.cpls().front()->set_mxf_keys (key ());
-	
+	shared_ptr<const dcp::CPL> cpl (new dcp::CPL (cpl_file));
 	return dcp::DecryptedKDM (
-		dcp.cpls().front(), from, until, "DCP-o-matic", dcp.cpls().front()->content_title_text(), dcp::LocalTime().as_string()
-		).encrypt (signer, target);
+		cpl, from, until, "DCP-o-matic", cpl->content_title_text(), dcp::LocalTime().as_string()
+		).encrypt (make_signer(), target);
 }
 
 list<dcp::EncryptedKDM>
diff --git a/src/lib/film.h b/src/lib/film.h
index ee8756b3d..d9d7e82fd 100644
--- a/src/lib/film.h
+++ b/src/lib/film.h
@@ -99,7 +99,7 @@ public:
 	dcp::Size full_frame () const;
 	dcp::Size frame_size () const;
 
-	std::list<boost::filesystem::path> dcps () const;
+	std::vector<CPLSummary> cpls () const;
 
 	boost::shared_ptr<Player> make_player () const;
 	boost::shared_ptr<Playlist> playlist () const;
@@ -120,14 +120,14 @@ public:
 	dcp::EncryptedKDM
 	make_kdm (
 		boost::shared_ptr<dcp::Certificate> target,
-		boost::filesystem::path dcp,
+		boost::filesystem::path cpl_file,
 		dcp::LocalTime from,
 		dcp::LocalTime until
 		) const;
 	
 	std::list<dcp::EncryptedKDM> make_kdms (
 		std::list<boost::shared_ptr<Screen> >,
-		boost::filesystem::path dcp,
+		boost::filesystem::path cpl_file,
 		dcp::LocalTime from,
 		dcp::LocalTime until
 		) const;
diff --git a/src/lib/image_decoder.cc b/src/lib/image_decoder.cc
index 9f83d1d89..d3cdbd6f1 100644
--- a/src/lib/image_decoder.cc
+++ b/src/lib/image_decoder.cc
@@ -49,7 +49,7 @@ ImageDecoder::pass ()
 
 	if (!_image_content->still() || !_image) {
 		/* Either we need an image or we are using moving images, so load one */
-		_image.reset (new MagickImageProxy (_image_content->path (_image_content->still() ? 0 : _video_position)));
+		_image.reset (new MagickImageProxy (_image_content->path (_image_content->still() ? 0 : _video_position), _image_content->film()->log ()));
 	}
 		
 	video (_image, _video_position);
diff --git a/src/lib/image_proxy.cc b/src/lib/image_proxy.cc
index c74e846c9..16bd92f6e 100644
--- a/src/lib/image_proxy.cc
+++ b/src/lib/image_proxy.cc
@@ -24,21 +24,32 @@
 #include "image.h"
 #include "exceptions.h"
 #include "cross.h"
+#include "log.h"
 
 #include "i18n.h"
 
+#define LOG_TIMING(...) _log->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
+
 using std::cout;
 using std::string;
 using std::stringstream;
 using boost::shared_ptr;
 
-RawImageProxy::RawImageProxy (shared_ptr<Image> image)
-	: _image (image)
+ImageProxy::ImageProxy (shared_ptr<Log> log)
+	: _log (log)
 {
 
 }
 
-RawImageProxy::RawImageProxy (shared_ptr<cxml::Node> xml, shared_ptr<Socket> socket)
+RawImageProxy::RawImageProxy (shared_ptr<Image> image, shared_ptr<Log> log)
+	: ImageProxy (log)
+	, _image (image)
+{
+
+}
+
+RawImageProxy::RawImageProxy (shared_ptr<cxml::Node> xml, shared_ptr<Socket> socket, shared_ptr<Log> log)
+	: ImageProxy (log)
 {
 	dcp::Size size (
 		xml->number_child<int> ("Width"), xml->number_child<int> ("Height")
@@ -68,7 +79,8 @@ RawImageProxy::send_binary (shared_ptr<Socket> socket) const
 	_image->write_to_socket (socket);
 }
 
-MagickImageProxy::MagickImageProxy (boost::filesystem::path path)
+MagickImageProxy::MagickImageProxy (boost::filesystem::path path, shared_ptr<Log> log)
+	: ImageProxy (log)
 {
 	/* Read the file into a Blob */
 	
@@ -89,7 +101,8 @@ MagickImageProxy::MagickImageProxy (boost::filesystem::path path)
 	delete[] data;
 }
 
-MagickImageProxy::MagickImageProxy (shared_ptr<cxml::Node>, shared_ptr<Socket> socket)
+MagickImageProxy::MagickImageProxy (shared_ptr<cxml::Node>, shared_ptr<Socket> socket, shared_ptr<Log> log)
+	: ImageProxy (log)
 {
 	uint32_t const size = socket->read_uint32 ();
 	uint8_t* data = new uint8_t[size];
@@ -105,6 +118,8 @@ MagickImageProxy::image () const
 		return _image;
 	}
 
+	LOG_TIMING ("[%1] MagickImageProxy begins decode and convert of %2 bytes", boost::this_thread::get_id(), _blob.length());
+
 	Magick::Image* magick_image = 0;
 	try {
 		magick_image = new Magick::Image (_blob);
@@ -113,6 +128,7 @@ MagickImageProxy::image () const
 	}
 
 	dcp::Size size (magick_image->columns(), magick_image->rows());
+	LOG_TIMING ("[%1] MagickImageProxy decode finished", boost::this_thread::get_id ());
 
 	_image.reset (new Image (PIX_FMT_RGB24, size, true));
 
@@ -132,6 +148,8 @@ MagickImageProxy::image () const
 
 	delete magick_image;
 
+	LOG_TIMING ("[%1] MagickImageProxy completes decode and convert of %2 bytes", boost::this_thread::get_id(), _blob.length());
+
 	return _image;
 }
 
@@ -149,12 +167,12 @@ MagickImageProxy::send_binary (shared_ptr<Socket> socket) const
 }
 
 shared_ptr<ImageProxy>
-image_proxy_factory (shared_ptr<cxml::Node> xml, shared_ptr<Socket> socket)
+image_proxy_factory (shared_ptr<cxml::Node> xml, shared_ptr<Socket> socket, shared_ptr<Log> log)
 {
 	if (xml->string_child("Type") == N_("Raw")) {
-		return shared_ptr<ImageProxy> (new RawImageProxy (xml, socket));
+		return shared_ptr<ImageProxy> (new RawImageProxy (xml, socket, log));
 	} else if (xml->string_child("Type") == N_("Magick")) {
-		return shared_ptr<MagickImageProxy> (new MagickImageProxy (xml, socket));
+		return shared_ptr<MagickImageProxy> (new MagickImageProxy (xml, socket, log));
 	}
 
 	throw NetworkError (_("Unexpected image type received by server"));
diff --git a/src/lib/image_proxy.h b/src/lib/image_proxy.h
index 792fa004a..b499b3292 100644
--- a/src/lib/image_proxy.h
+++ b/src/lib/image_proxy.h
@@ -28,6 +28,7 @@
 
 class Image;
 class Socket;
+class Log;
 
 namespace cxml {
 	class Node;
@@ -44,19 +45,24 @@ namespace cxml {
  *  the TIFF data TIFF until such a time that the actual image is needed.
  *  At this point, the class decodes the TIFF to an Image.
  */
-class ImageProxy
+class ImageProxy : public boost::noncopyable
 {
 public:
+	ImageProxy (boost::shared_ptr<Log> log);
+	
 	virtual boost::shared_ptr<Image> image () const = 0;
 	virtual void add_metadata (xmlpp::Node *) const = 0;
 	virtual void send_binary (boost::shared_ptr<Socket>) const = 0;
+
+protected:
+	boost::shared_ptr<Log> _log;
 };
 
 class RawImageProxy : public ImageProxy
 {
 public:
-	RawImageProxy (boost::shared_ptr<Image>);
-	RawImageProxy (boost::shared_ptr<cxml::Node> xml, boost::shared_ptr<Socket> socket);
+	RawImageProxy (boost::shared_ptr<Image>, boost::shared_ptr<Log> log);
+	RawImageProxy (boost::shared_ptr<cxml::Node> xml, boost::shared_ptr<Socket> socket, boost::shared_ptr<Log> log);
 
 	boost::shared_ptr<Image> image () const;
 	void add_metadata (xmlpp::Node *) const;
@@ -69,8 +75,8 @@ private:
 class MagickImageProxy : public ImageProxy
 {
 public:
-	MagickImageProxy (boost::filesystem::path);
-	MagickImageProxy (boost::shared_ptr<cxml::Node> xml, boost::shared_ptr<Socket> socket);
+	MagickImageProxy (boost::filesystem::path, boost::shared_ptr<Log> log);
+	MagickImageProxy (boost::shared_ptr<cxml::Node> xml, boost::shared_ptr<Socket> socket, boost::shared_ptr<Log> log);
 
 	boost::shared_ptr<Image> image () const;
 	void add_metadata (xmlpp::Node *) const;
@@ -81,4 +87,4 @@ private:
 	mutable boost::shared_ptr<Image> _image;
 };
 
-boost::shared_ptr<ImageProxy> image_proxy_factory (boost::shared_ptr<cxml::Node> xml, boost::shared_ptr<Socket> socket);
+boost::shared_ptr<ImageProxy> image_proxy_factory (boost::shared_ptr<cxml::Node> xml, boost::shared_ptr<Socket> socket, boost::shared_ptr<Log> log);
diff --git a/src/lib/job.cc b/src/lib/job.cc
index c6a6b90a8..594c0da34 100644
--- a/src/lib/job.cc
+++ b/src/lib/job.cc
@@ -281,7 +281,7 @@ Job::error_summary () const
 void
 Job::set_error (string s, string d)
 {
-	_film->log()->log (String::compose ("Error in job: %1 (%2)", s, d));
+	_film->log()->log (String::compose ("Error in job: %1 (%2)", s, d), Log::TYPE_ERROR);
 	boost::mutex::scoped_lock lm (_state_mutex);
 	_error_summary = s;
 	_error_details = d;
diff --git a/src/lib/kdm.cc b/src/lib/kdm.cc
index 902f0d333..c08750961 100644
--- a/src/lib/kdm.cc
+++ b/src/lib/kdm.cc
@@ -102,12 +102,12 @@ static list<ScreenKDM>
 make_screen_kdms (
 	shared_ptr<const Film> film,
 	list<shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to
 	)
 {
-	list<dcp::EncryptedKDM> kdms = film->make_kdms (screens, dcp, from, to);
+	list<dcp::EncryptedKDM> kdms = film->make_kdms (screens, cpl, from, to);
 	   
 	list<ScreenKDM> screen_kdms;
 	
@@ -126,12 +126,12 @@ static list<CinemaKDMs>
 make_cinema_kdms (
 	shared_ptr<const Film> film,
 	list<shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to
 	)
 {
-	list<ScreenKDM> screen_kdms = make_screen_kdms (film, screens, dcp, from, to);
+	list<ScreenKDM> screen_kdms = make_screen_kdms (film, screens, cpl, from, to);
 	list<CinemaKDMs> cinema_kdms;
 
 	while (!screen_kdms.empty ()) {
@@ -171,13 +171,13 @@ void
 write_kdm_files (
 	shared_ptr<const Film> film,
 	list<shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to,
 	boost::filesystem::path directory
 	)
 {
-	list<ScreenKDM> screen_kdms = make_screen_kdms (film, screens, dcp, from, to);
+	list<ScreenKDM> screen_kdms = make_screen_kdms (film, screens, cpl, from, to);
 
 	/* Write KDMs to the specified directory */
 	for (list<ScreenKDM>::iterator i = screen_kdms.begin(); i != screen_kdms.end(); ++i) {
@@ -191,13 +191,13 @@ void
 write_kdm_zip_files (
 	shared_ptr<const Film> film,
 	list<shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to,
 	boost::filesystem::path directory
 	)
 {
-	list<CinemaKDMs> cinema_kdms = make_cinema_kdms (film, screens, dcp, from, to);
+	list<CinemaKDMs> cinema_kdms = make_cinema_kdms (film, screens, cpl, from, to);
 
 	for (list<CinemaKDMs>::const_iterator i = cinema_kdms.begin(); i != cinema_kdms.end(); ++i) {
 		boost::filesystem::path path = directory;
@@ -210,12 +210,12 @@ void
 email_kdms (
 	shared_ptr<const Film> film,
 	list<shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to
 	)
 {
-	list<CinemaKDMs> cinema_kdms = make_cinema_kdms (film, screens, dcp, from, to);
+	list<CinemaKDMs> cinema_kdms = make_cinema_kdms (film, screens, cpl, from, to);
 
 	for (list<CinemaKDMs>::const_iterator i = cinema_kdms.begin(); i != cinema_kdms.end(); ++i) {
 		
diff --git a/src/lib/kdm.h b/src/lib/kdm.h
index 5df161b2a..023107a82 100644
--- a/src/lib/kdm.h
+++ b/src/lib/kdm.h
@@ -26,7 +26,7 @@ class Film;
 extern void write_kdm_files (
 	boost::shared_ptr<const Film> film,
 	std::list<boost::shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to,
 	boost::filesystem::path directory
@@ -35,7 +35,7 @@ extern void write_kdm_files (
 extern void write_kdm_zip_files (
 	boost::shared_ptr<const Film> film,
 	std::list<boost::shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to,
 	boost::filesystem::path directory
@@ -44,7 +44,7 @@ extern void write_kdm_zip_files (
 extern void email_kdms (
 	boost::shared_ptr<const Film> film,
 	std::list<boost::shared_ptr<Screen> > screens,
-	boost::filesystem::path dcp,
+	boost::filesystem::path cpl,
 	dcp::LocalTime from,
 	dcp::LocalTime to
 	);
diff --git a/src/lib/log.cc b/src/lib/log.cc
index a0b031589..52dff2982 100644
--- a/src/lib/log.cc
+++ b/src/lib/log.cc
@@ -25,24 +25,37 @@
 #include <cstdio>
 #include "log.h"
 #include "cross.h"
+#include "config.h"
 
 #include "i18n.h"
 
 using namespace std;
 
+int const Log::TYPE_GENERAL = 0x1;
+int const Log::TYPE_WARNING = 0x2;
+int const Log::TYPE_ERROR   = 0x4;
+int const Log::TYPE_TIMING  = 0x8;
+
 Log::Log ()
-	: _level (STANDARD)
+	: _types (0)
 {
+	Config::instance()->Changed.connect (boost::bind (&Log::config_changed, this));
+	config_changed ();
+}
 
+void
+Log::config_changed ()
+{
+	set_types (Config::instance()->log_types ());
 }
 
 /** @param n String to log */
 void
-Log::log (string m, Level l)
+Log::log (string message, int type)
 {
 	boost::mutex::scoped_lock lm (_mutex);
 
-	if (l > _level) {
+	if ((_types & type) == 0) {
 		return;
 	}
 
@@ -51,16 +64,26 @@ Log::log (string m, Level l)
 	string a = ctime (&t);
 
 	stringstream s;
-	s << a.substr (0, a.length() - 1) << N_(": ") << m;
+	s << a.substr (0, a.length() - 1) << N_(": ");
+
+	if (type & TYPE_ERROR) {
+		s << "ERROR: ";
+	}
+
+	if (type & TYPE_WARNING) {
+		s << "WARNING: ";
+	}
+	
+	s << message;
 	do_log (s.str ());
 }
 
 void
-Log::microsecond_log (string m, Level l)
+Log::microsecond_log (string m, int t)
 {
 	boost::mutex::scoped_lock lm (_mutex);
 
-	if (l > _level) {
+	if ((_types & t) == 0) {
 		return;
 	}
 
@@ -73,24 +96,10 @@ Log::microsecond_log (string m, Level l)
 }	
 
 void
-Log::set_level (Level l)
+Log::set_types (int t)
 {
 	boost::mutex::scoped_lock lm (_mutex);
-	_level = l;
-}
-
-void
-Log::set_level (string l)
-{
-	if (l == N_("verbose")) {
-		set_level (VERBOSE);
-		return;
-	} else if (l == N_("timing")) {
-		set_level (TIMING);
-		return;
-	}
-
-	set_level (STANDARD);
+	_types = t;
 }
 
 /** @param file Filename to write log to */
diff --git a/src/lib/log.h b/src/lib/log.h
index 991532404..2ba273b44 100644
--- a/src/lib/log.h
+++ b/src/lib/log.h
@@ -37,17 +37,15 @@ public:
 	Log ();
 	virtual ~Log () {}
 
-	enum Level {
-		STANDARD = 0,
-		VERBOSE = 1,
-		TIMING = 2
-	};
+	static const int TYPE_GENERAL;
+	static const int TYPE_WARNING;
+	static const int TYPE_ERROR;
+	static const int TYPE_TIMING;
 
-	void log (std::string m, Level l = STANDARD);
-	void microsecond_log (std::string m, Level l = STANDARD);
+	void log (std::string message, int type);
+	void microsecond_log (std::string message, int type);
 
-	void set_level (Level l);
-	void set_level (std::string l);
+	void set_types (int types);
 
 protected:	
 	/** mutex to protect the log */
@@ -55,9 +53,10 @@ protected:
 	
 private:
 	virtual void do_log (std::string m) = 0;
+	void config_changed ();
 	
-	/** level above which to ignore log messages */
-	Level _level;
+	/** bit-field of log types which should be put into the log (others are ignored) */
+	int _types;
 };
 
 class FileLog : public Log
diff --git a/src/lib/player.cc b/src/lib/player.cc
index b60dd8467..77def1e60 100644
--- a/src/lib/player.cc
+++ b/src/lib/player.cc
@@ -43,6 +43,8 @@
 #include "content_video.h"
 #include "player_video_frame.h"
 
+#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+
 using std::list;
 using std::cout;
 using std::min;
@@ -293,7 +295,7 @@ Player::black_player_video_frame () const
 {
 	return shared_ptr<PlayerVideoFrame> (
 		new PlayerVideoFrame (
-			shared_ptr<const ImageProxy> (new RawImageProxy (_black_image)),
+			shared_ptr<const ImageProxy> (new RawImageProxy (_black_image, _film->log ())),
 			Crop (),
 			_video_container_size,
 			_video_container_size,
@@ -496,8 +498,6 @@ Player::get_audio (DCPTime time, DCPTime length, bool accurate)
 			min (AudioFrame (all->audio->frames()), length_frames) - offset.frames (_film->audio_frame_rate ())
 			);
 	}
-
-	return audio;
 }
 
 VideoFrame
@@ -538,8 +538,8 @@ Player::dcp_to_content_subtitle (shared_ptr<const Piece> piece, DCPTime t) const
 void
 PlayerStatistics::dump (shared_ptr<Log> log) const
 {
-	log->log (String::compose ("Video: %1 good %2 skipped %3 black %4 repeat", video.good, video.skip, video.black, video.repeat));
-	log->log (String::compose ("Audio: %1 good %2 skipped %3 silence", audio.good, audio.skip, audio.silence.seconds()));
+	log->log (String::compose ("Video: %1 good %2 skipped %3 black %4 repeat", video.good, video.skip, video.black, video.repeat), Log::TYPE_GENERAL);
+	log->log (String::compose ("Audio: %1 good %2 skipped %3 silence", audio.good, audio.skip, audio.silence.seconds()), Log::TYPE_GENERAL);
 }
 
 PlayerStatistics const &
diff --git a/src/lib/player_video_frame.cc b/src/lib/player_video_frame.cc
index 2544f8bbc..5463925bf 100644
--- a/src/lib/player_video_frame.cc
+++ b/src/lib/player_video_frame.cc
@@ -50,7 +50,7 @@ PlayerVideoFrame::PlayerVideoFrame (
 
 }
 
-PlayerVideoFrame::PlayerVideoFrame (shared_ptr<cxml::Node> node, shared_ptr<Socket> socket)
+PlayerVideoFrame::PlayerVideoFrame (shared_ptr<cxml::Node> node, shared_ptr<Socket> socket, shared_ptr<Log> log)
 {
 	_crop = Crop (node);
 
@@ -61,7 +61,7 @@ PlayerVideoFrame::PlayerVideoFrame (shared_ptr<cxml::Node> node, shared_ptr<Sock
 	_part = (Part) node->number_child<int> ("Part");
 	_colour_conversion = ColourConversion (node);
 
-	_in = image_proxy_factory (node->node_child ("In"), socket);
+	_in = image_proxy_factory (node->node_child ("In"), socket, log);
 
 	if (node->optional_number_child<int> ("SubtitleX")) {
 		
diff --git a/src/lib/player_video_frame.h b/src/lib/player_video_frame.h
index 225b0a4ba..4c6a9c630 100644
--- a/src/lib/player_video_frame.h
+++ b/src/lib/player_video_frame.h
@@ -27,6 +27,7 @@ class Image;
 class ImageProxy;
 class Scaler;
 class Socket;
+class Log;
 
 /** Everything needed to describe a video frame coming out of the player, but with the
  *  bits still their raw form.  We may want to combine the bits on a remote machine,
@@ -36,7 +37,7 @@ class PlayerVideoFrame
 {
 public:
 	PlayerVideoFrame (boost::shared_ptr<const ImageProxy>, Crop, dcp::Size, dcp::Size, Scaler const *, Eyes, Part, ColourConversion);
-	PlayerVideoFrame (boost::shared_ptr<cxml::Node>, boost::shared_ptr<Socket>);
+	PlayerVideoFrame (boost::shared_ptr<cxml::Node>, boost::shared_ptr<Socket>, boost::shared_ptr<Log>);
 
 	void set_subtitle (PositionImage);
 	
diff --git a/src/lib/scp_dcp_job.cc b/src/lib/scp_dcp_job.cc
index 0b713b042..637840813 100644
--- a/src/lib/scp_dcp_job.cc
+++ b/src/lib/scp_dcp_job.cc
@@ -37,6 +37,8 @@
 
 #include "i18n.h"
 
+#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL);
+
 using std::string;
 using std::stringstream;
 using std::min;
@@ -119,7 +121,7 @@ SCPDCPJob::json_name () const
 void
 SCPDCPJob::run ()
 {
-	_film->log()->log (N_("SCP DCP job starting"));
+	LOG_GENERAL_NC (N_("SCP DCP job starting"));
 	
 	SSHSession ss;
 	
diff --git a/src/lib/server.cc b/src/lib/server.cc
index d72b7e502..507ff2ae5 100644
--- a/src/lib/server.cc
+++ b/src/lib/server.cc
@@ -41,6 +41,11 @@
 
 #include "i18n.h"
 
+#define LOG_GENERAL(...)    _log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_GENERAL_NC(...) _log->log (__VA_ARGS__, Log::TYPE_GENERAL);
+#define LOG_ERROR(...)      _log->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_ERROR_NC(...)   _log->log (__VA_ARGS__, Log::TYPE_ERROR);
+
 using std::string;
 using std::stringstream;
 using std::multimap;
@@ -82,11 +87,11 @@ Server::process (shared_ptr<Socket> socket, struct timeval& after_read, struct t
 	xml->read_stream (s);
 	if (xml->number_child<int> ("Version") != SERVER_LINK_VERSION) {
 		cerr << "Mismatched server/client versions\n";
-		_log->log ("Mismatched server/client versions");
+		LOG_ERROR_NC ("Mismatched server/client versions");
 		return -1;
 	}
 
-	shared_ptr<PlayerVideoFrame> pvf (new PlayerVideoFrame (xml, socket));
+	shared_ptr<PlayerVideoFrame> pvf (new PlayerVideoFrame (xml, socket, _log));
 
 	DCPVideoFrame dcp_video_frame (pvf, xml, _log);
 
@@ -99,7 +104,7 @@ Server::process (shared_ptr<Socket> socket, struct timeval& after_read, struct t
 	try {
 		encoded->send (socket);
 	} catch (std::exception& e) {
-		_log->log (String::compose ("Send failed; frame %1", dcp_video_frame.index()));
+		LOG_ERROR ("Send failed; frame %1", dcp_video_frame.index());
 		throw;
 	}
 
@@ -134,7 +139,7 @@ Server::worker_thread ()
 			frame = process (socket, after_read, after_encode);
 			ip = socket->socket().remote_endpoint().address().to_string();
 		} catch (std::exception& e) {
-			_log->log (String::compose ("Error: %1", e.what()));
+			LOG_ERROR ("Error: %1", e.what());
 		}
 
 		gettimeofday (&end, 0);
@@ -159,7 +164,7 @@ Server::worker_thread ()
 				cout << message.str() << "\n";
 			}
 
-			_log->log (message.str ());
+			LOG_GENERAL_NC (message.str ());
 		}
 		
 		_worker_condition.notify_all ();
@@ -169,7 +174,7 @@ Server::worker_thread ()
 void
 Server::run (int num_threads)
 {
-	_log->log (String::compose ("Server starting with %1 threads", num_threads));
+	LOG_GENERAL ("Server starting with %1 threads", num_threads);
 	if (_verbose) {
 		cout << "DCP-o-matic server starting with " << num_threads << " threads.\n";
 	}
diff --git a/src/lib/transcode_job.cc b/src/lib/transcode_job.cc
index 97e8bd416..4a85fa18a 100644
--- a/src/lib/transcode_job.cc
+++ b/src/lib/transcode_job.cc
@@ -30,6 +30,9 @@
 
 #include "i18n.h"
 
+#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL);
+#define LOG_ERROR_NC(...)   _film->log()->log (__VA_ARGS__, Log::TYPE_ERROR);
+
 using std::string;
 using std::stringstream;
 using std::fixed;
@@ -62,17 +65,20 @@ TranscodeJob::run ()
 {
 	try {
 
-		_film->log()->log (N_("Transcode job starting"));
+		LOG_GENERAL_NC (N_("Transcode job starting"));
 
 		_transcoder.reset (new Transcoder (_film, shared_from_this ()));
 		_transcoder->go ();
 		set_progress (1);
 		set_state (FINISHED_OK);
 
-		_film->log()->log (N_("Transcode job completed successfully"));
+		LOG_GENERAL_NC (N_("Transcode job completed successfully"));
 		_transcoder.reset ();
 
 	} catch (...) {
+		set_progress (1);
+		set_state (FINISHED_ERROR);
+		LOG_ERROR_NC (N_("Transcode job failed or cancelled"));
 		_transcoder.reset ();
 		throw;
 	}
diff --git a/src/lib/types.h b/src/lib/types.h
index e858d1e1f..9a6a30b86 100644
--- a/src/lib/types.h
+++ b/src/lib/types.h
@@ -138,6 +138,21 @@ struct Crop
 	void as_xml (xmlpp::Node *) const;
 };
 
+struct CPLSummary
+{
+	CPLSummary (std::string d, std::string i, std::string a, boost::filesystem::path f)
+		: dcp_directory (d)
+		, cpl_id (i)
+		, cpl_annotation_text (a)
+		, cpl_file (f)
+	{}
+	
+	std::string dcp_directory;
+	std::string cpl_id;
+	std::string cpl_annotation_text;
+	boost::filesystem::path cpl_file;
+};
+
 extern bool operator== (Crop const & a, Crop const & b);
 extern bool operator!= (Crop const & a, Crop const & b);
 
diff --git a/src/lib/util.h b/src/lib/util.h
index 196a6e8f9..28af8ef2f 100644
--- a/src/lib/util.h
+++ b/src/lib/util.h
@@ -41,12 +41,6 @@ extern "C" {
 #include "types.h"
 #include "video_content.h"
 
-#ifdef DCPOMATIC_DEBUG
-#define TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TIMING);
-#else
-#define TIMING(...)
-#endif
-
 #undef check
 
 /** The maximum number of audio channels that we can have in a DCP */
diff --git a/src/lib/writer.cc b/src/lib/writer.cc
index 306f6d7f4..9410dd565 100644
--- a/src/lib/writer.cc
+++ b/src/lib/writer.cc
@@ -45,6 +45,10 @@
 
 #include "i18n.h"
 
+#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);
+
 /* OS X strikes again */
 #undef set_key
 
@@ -242,9 +246,9 @@ try
 				break;
 			}
 
-			TIMING (N_("writer sleeps with a queue of %1"), _queue.size());
+			LOG_TIMING (N_("writer sleeps with a queue of %1"), _queue.size());
 			_empty_condition.wait (lock);
-			TIMING (N_("writer wakes with a queue of %1"), _queue.size());
+			LOG_TIMING (N_("writer wakes with a queue of %1"), _queue.size());
 		}
 
 		if (_finish && _queue.empty()) {
@@ -263,7 +267,7 @@ try
 			switch (qi.type) {
 			case QueueItem::FULL:
 			{
-				_film->log()->log (String::compose (N_("Writer FULL-writes %1 to MXF"), qi.frame));
+				LOG_GENERAL (N_("Writer FULL-writes %1 to MXF"), qi.frame);
 				if (!qi.encoded) {
 					qi.encoded.reset (new EncodedData (_film->j2c_path (qi.frame, qi.eyes, false)));
 				}
@@ -275,7 +279,7 @@ try
 				break;
 			}
 			case QueueItem::FAKE:
-				_film->log()->log (String::compose (N_("Writer FAKE-writes %1 to MXF"), qi.frame));
+				LOG_GENERAL (N_("Writer FAKE-writes %1 to MXF"), qi.frame);
 				_picture_mxf_writer->fake_write (qi.size);
 				_last_written[qi.eyes].reset ();
 				++_fake_written;
@@ -319,11 +323,10 @@ try
 			
 			lock.unlock ();
 
-			_film->log()->log (
-				String::compose (
-					"Writer full (awaiting %1 [last eye was %2]); pushes %3 to disk",
-					_last_written_frame + 1,
-					_last_written_eyes, qi.frame)
+			LOG_GENERAL (
+				"Writer full (awaiting %1 [last eye was %2]); pushes %3 to disk",
+				_last_written_frame + 1,
+				_last_written_eyes, qi.frame
 				);
 			
 			qi.encoded->write (_film, qi.frame, qi.eyes);
@@ -390,7 +393,7 @@ Writer::finish ()
 	if (ec) {
 		/* hard link failed; copy instead */
 		boost::filesystem::copy_file (video_from, video_to);
-		_film->log()->log ("Hard-link failed; fell back to copying");
+		LOG_WARNING_NC ("Hard-link failed; fell back to copying");
 	}
 
 	_picture_mxf->set_file (video_to);
@@ -460,8 +463,8 @@ Writer::finish ()
 
 	dcp.write_xml (_film->interop () ? dcp::INTEROP : dcp::SMPTE, meta, _film->is_signed() ? make_signer () : shared_ptr<const dcp::Signer> ());
 
-	_film->log()->log (
-		String::compose (N_("Wrote %1 FULL, %2 FAKE, %3 pushed to disk"), _full_written, _fake_written, _pushed_to_disk)
+	LOG_GENERAL (
+		N_("Wrote %1 FULL, %2 FAKE, %3 pushed to disk"), _full_written, _fake_written, _pushed_to_disk
 		);
 }
 
@@ -471,14 +474,14 @@ Writer::check_existing_picture_mxf_frame (FILE* mxf, int f, Eyes eyes)
 	/* Read the frame info as written */
 	FILE* ifi = fopen_boost (_film->info_path (f, eyes), "r");
 	if (!ifi) {
-		_film->log()->log (String::compose ("Existing frame %1 has no info file", f));
+		LOG_GENERAL ("Existing frame %1 has no info file", f);
 		return false;
 	}
 	
 	dcp::FrameInfo info (ifi);
 	fclose (ifi);
 	if (info.size == 0) {
-		_film->log()->log (String::compose ("Existing frame %1 has no info file", f));
+		LOG_GENERAL ("Existing frame %1 has no info file", f);
 		return false;
 	}
 	
@@ -487,13 +490,13 @@ Writer::check_existing_picture_mxf_frame (FILE* mxf, int f, Eyes eyes)
 	EncodedData data (info.size);
 	size_t const read = fread (data.data(), 1, data.size(), mxf);
 	if (read != static_cast<size_t> (data.size ())) {
-		_film->log()->log (String::compose ("Existing frame %1 is incomplete", f));
+		LOG_GENERAL ("Existing frame %1 is incomplete", f);
 		return false;
 	}
 	
 	string const existing_hash = md5_digest (data.data(), data.size());
 	if (existing_hash != info.hash) {
-		_film->log()->log (String::compose ("Existing frame %1 failed hash check", f));
+		LOG_GENERAL ("Existing frame %1 failed hash check", f);
 		return false;
 	}
 
@@ -509,7 +512,7 @@ Writer::check_existing_picture_mxf ()
 	p /= _film->internal_video_mxf_filename ();
 	FILE* mxf = fopen_boost (p, "rb");
 	if (!mxf) {
-		_film->log()->log (String::compose ("Could not open existing MXF at %1 (errno=%2)", p.string(), errno));
+		LOG_GENERAL ("Could not open existing MXF at %1 (errno=%2)", p.string(), errno);
 		return;
 	}
 
@@ -540,7 +543,7 @@ Writer::check_existing_picture_mxf ()
 			}
 		}
 
-		_film->log()->log (String::compose ("Have existing frame %1", _first_nonexistant_frame));
+		LOG_GENERAL ("Have existing frame %1", _first_nonexistant_frame);
 		++_first_nonexistant_frame;
 	}