# HG changeset patch
# User Chris Cannam
# Date 1479832841 0
# Node ID 0a9193dc136bca2ec1d737ee34631db89974a685
# Parent  0be27c989c1d0c9f0882838f7393388d70b01f24
Debug output updates

diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/AudioFileReaderFactory.cpp
--- a/data/fileio/AudioFileReaderFactory.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/AudioFileReaderFactory.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -29,8 +29,6 @@
 #include <QFileInfo>
 #include <iostream>
 
-//#define DEBUG_AUDIO_FILE_READER_FACTORY 1
-
 QString
 AudioFileReaderFactory::getKnownExtensions()
 {
@@ -89,17 +87,15 @@
 {
     QString err;
 
-#ifdef DEBUG_AUDIO_FILE_READER_FACTORY
-    cerr << "AudioFileReaderFactory::createReader(\"" << source.getLocation() << "\"): Requested rate: " << targetRate << endl;
-#endif
+    SVDEBUG << "AudioFileReaderFactory::createReader(\"" << source.getLocation() << "\"): Requested rate: " << targetRate << (targetRate == 0 ? " (use source rate)" : "") << endl;
 
     if (!source.isOK()) {
-        cerr << "AudioFileReaderFactory::createReader(\"" << source.getLocation() << "\": Failed to retrieve source (transmission error?): " << source.getErrorString() << endl;
+        SVDEBUG << "AudioFileReaderFactory::createReader(\"" << source.getLocation() << "\": Failed to retrieve source (transmission error?): " << source.getErrorString() << endl;
         return 0;
     }
 
     if (!source.isAvailable()) {
-        cerr << "AudioFileReaderFactory::createReader(\"" << source.getLocation() << "\": Source not found" << endl;
+        SVDEBUG << "AudioFileReaderFactory::createReader(\"" << source.getLocation() << "\": Source not found" << endl;
         return 0;
     }
 
@@ -143,9 +139,7 @@
              (cacheMode == CodedAudioFileReader::CacheInMemory) ||
              (targetRate != 0 && fileRate != targetRate))) {
 
-#ifdef DEBUG_AUDIO_FILE_READER_FACTORY
-            cerr << "AudioFileReaderFactory::createReader: WAV file rate: " << reader->getSampleRate() << ", normalised " << normalised << ", seekable " << reader->isQuicklySeekable() << ", in memory " << (cacheMode == CodedAudioFileReader::CacheInMemory) << ", creating decoding reader" << endl;
-#endif
+            SVDEBUG << "AudioFileReaderFactory::createReader: WAV file rate: " << reader->getSampleRate() << ", normalised " << normalised << ", seekable " << reader->isQuicklySeekable() << ", in memory " << (cacheMode == CodedAudioFileReader::CacheInMemory) << ", creating decoding reader" << endl;
             
             delete reader;
             reader = new DecodingWavFileReader
@@ -214,9 +208,7 @@
          (cacheMode == CodedAudioFileReader::CacheInMemory) ||
          (targetRate != 0 && fileRate != targetRate))) {
 
-#ifdef DEBUG_AUDIO_FILE_READER_FACTORY
-        cerr << "AudioFileReaderFactory::createReader: WAV file rate: " << reader->getSampleRate() << ", normalised " << normalised << ", seekable " << reader->isQuicklySeekable() << ", in memory " << (cacheMode == CodedAudioFileReader::CacheInMemory) << ", creating decoding reader" << endl;
-#endif
+        SVDEBUG << "AudioFileReaderFactory::createReader: WAV file rate: " << reader->getSampleRate() << ", normalised " << normalised << ", seekable " << reader->isQuicklySeekable() << ", in memory " << (cacheMode == CodedAudioFileReader::CacheInMemory) << ", creating decoding reader" << endl;
 
         delete reader;
         reader = new DecodingWavFileReader
@@ -264,10 +256,10 @@
 #endif
 
     if (!reader) {
-        cerr << "AudioFileReaderFactory::Failed to create a reader for "
-             << "url \"" << source.getLocation()
-             << "\" (content type \""
-             << source.getContentType() << "\")" << endl;
+        SVDEBUG << "AudioFileReaderFactory::Failed to create a reader for "
+                << "url \"" << source.getLocation()
+                << "\" (content type \""
+                << source.getContentType() << "\")" << endl;
         return nullptr;
     }
     
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/CodedAudioFileReader.cpp
--- a/data/fileio/CodedAudioFileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/CodedAudioFileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -49,7 +49,12 @@
     m_max(0.f),
     m_gain(1.f)
 {
-    SVDEBUG << "CodedAudioFileReader::CodedAudioFileReader: rate " << targetRate << ", normalised = " << normalised << endl;
+    SVDEBUG << "CodedAudioFileReader:: cache mode: " << cacheMode
+            << " (" << (cacheMode == CacheInTemporaryFile
+                        ? "CacheInTemporaryFile" : "CacheInMemory") << ")"
+            << ", rate: " << targetRate
+            << (targetRate == 0 ? " (use source rate)" : "")
+            << ", normalised: " << normalised << endl;
 
     m_frameCount = 0;
     m_sampleRate = targetRate;
@@ -59,7 +64,7 @@
 {
     QMutexLocker locker(&m_cacheMutex);
 
-    endSerialised();
+    if (m_serialiser) endSerialised();
     
     if (m_cacheFileWritePtr) sf_close(m_cacheFileWritePtr);
 
@@ -67,10 +72,11 @@
 
     delete m_cacheFileReader;
     delete[] m_cacheWriteBuffer;
-
+    
     if (m_cacheFileName != "") {
+        SVDEBUG << "CodedAudioFileReader::~CodedAudioFileReader: deleting cache file " << m_cacheFileName << endl;
         if (!QFile(m_cacheFileName).remove()) {
-            cerr << "WARNING: CodedAudioFileReader::~CodedAudioFileReader: Failed to delete cache file \"" << m_cacheFileName << "\"" << endl;
+            SVDEBUG << "WARNING: CodedAudioFileReader::~CodedAudioFileReader: Failed to delete cache file \"" << m_cacheFileName << "\"" << endl;
         }
     }
 
@@ -87,7 +93,7 @@
 void
 CodedAudioFileReader::startSerialised(QString id)
 {
-    SVDEBUG << "CodedAudioFileReader::startSerialised(" << id << ")" << endl;
+    SVDEBUG << "CodedAudioFileReader(" << this << ")::startSerialised: id = " << id << endl;
 
     delete m_serialiser;
     m_serialiser = new Serialiser(id);
@@ -110,7 +116,7 @@
     SVDEBUG << "CodedAudioFileReader::initialiseDecodeCache: file rate = " << m_fileRate << endl;
 
     if (m_fileRate == 0) {
-        cerr << "CodedAudioFileReader::initialiseDecodeCache: ERROR: File sample rate unknown (bug in subclass implementation?)" << endl;
+        SVDEBUG << "CodedAudioFileReader::initialiseDecodeCache: ERROR: File sample rate unknown (bug in subclass implementation?)" << endl;
         throw FileOperationFailed("(coded file)", "File sample rate unknown (bug in subclass implementation?)");
     }
     if (m_sampleRate == 0) {
@@ -140,7 +146,7 @@
             SF_INFO fileInfo;
             int fileRate = int(round(m_sampleRate));
             if (m_sampleRate != sv_samplerate_t(fileRate)) {
-                cerr << "CodedAudioFileReader: WARNING: Non-integer sample rate "
+                SVDEBUG << "CodedAudioFileReader: WARNING: Non-integer sample rate "
                      << m_sampleRate << " presented for writing, rounding to " << fileRate
                      << endl;
             }
@@ -181,7 +187,7 @@
                 m_cacheFileReader = new WavFileReader(m_cacheFileName);
 
                 if (!m_cacheFileReader->isOK()) {
-                    cerr << "ERROR: CodedAudioFileReader::initialiseDecodeCache: Failed to construct WAV file reader for temporary file: " << m_cacheFileReader->getError() << endl;
+                    SVDEBUG << "ERROR: CodedAudioFileReader::initialiseDecodeCache: Failed to construct WAV file reader for temporary file: " << m_cacheFileReader->getError() << endl;
                     delete m_cacheFileReader;
                     m_cacheFileReader = 0;
                     m_cacheMode = CacheInMemory;
@@ -189,12 +195,12 @@
                 }
 
             } else {
-                cerr << "CodedAudioFileReader::initialiseDecodeCache: failed to open cache file \"" << m_cacheFileName << "\" (" << m_channelCount << " channels, sample rate " << m_sampleRate << " for writing, falling back to in-memory cache" << endl;
+                SVDEBUG << "CodedAudioFileReader::initialiseDecodeCache: failed to open cache file \"" << m_cacheFileName << "\" (" << m_channelCount << " channels, sample rate " << m_sampleRate << " for writing, falling back to in-memory cache" << endl;
                 m_cacheMode = CacheInMemory;
             }
 
         } catch (DirectoryCreationFailed f) {
-            cerr << "CodedAudioFileReader::initialiseDecodeCache: failed to create temporary directory! Falling back to in-memory cache" << endl;
+            SVDEBUG << "CodedAudioFileReader::initialiseDecodeCache: failed to create temporary directory! Falling back to in-memory cache" << endl;
             m_cacheMode = CacheInMemory;
         }
     }
@@ -299,7 +305,7 @@
     Profiler profiler("CodedAudioFileReader::finishDecodeCache", true);
 
     if (!m_initialised) {
-        cerr << "WARNING: CodedAudioFileReader::finishDecodeCache: Cache was never initialised!" << endl;
+        SVDEBUG << "WARNING: CodedAudioFileReader::finishDecodeCache: Cache was never initialised!" << endl;
         return;
     }
 
@@ -468,7 +474,6 @@
         sv_frame_t ix0 = start * m_channelCount;
         sv_frame_t ix1 = ix0 + (count * m_channelCount);
 
-
         // This lock used to be a QReadWriteLock, but it appears that
         // its lock mechanism is significantly slower than QMutex so
         // it's not a good idea in cases like this where we don't
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/CoreAudioFileReader.cpp
--- a/data/fileio/CoreAudioFileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/CoreAudioFileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -71,6 +71,8 @@
     m_completion(0),
     m_decodeThread(0)
 {
+    SVDEBUG << "CoreAudioFileReader: local path: \"" << m_path << "\"" << endl;
+
     m_channelCount = 0;
     m_fileRate = 0;
 
@@ -78,8 +80,6 @@
 
     Profiler profiler("CoreAudioFileReader::CoreAudioFileReader", true);
 
-    SVDEBUG << "CoreAudioFileReader: path is \"" << m_path << "\"" << endl;
-
     QByteArray ba = m_path.toLocal8Bit();
 
     CFURLRef url = CFURLCreateFromFileSystemRepresentation
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/DecodingWavFileReader.cpp
--- a/data/fileio/DecodingWavFileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/DecodingWavFileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -39,12 +39,14 @@
     m_reporter(reporter),
     m_decodeThread(0)
 {
+    SVDEBUG << "DecodingWavFileReader: local path: \"" << m_path
+            << "\", decode mode: " << decodeMode << " ("
+            << (decodeMode == DecodeAtOnce ? "DecodeAtOnce" : "DecodeThreaded")
+            << ")" << endl;
+
     m_channelCount = 0;
     m_fileRate = 0;
 
-    SVDEBUG << "DecodingWavFileReader::DecodingWavFileReader(\""
-              << m_path << "\"): rate " << targetRate << endl;
-
     Profiler profiler("DecodingWavFileReader::DecodingWavFileReader", true);
 
     m_original = new WavFileReader(m_path);
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/MP3FileReader.cpp
--- a/data/fileio/MP3FileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/MP3FileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -50,6 +50,11 @@
     m_path(source.getLocalFilename()),
     m_decodeThread(0)
 {
+    SVDEBUG << "MP3FileReader: local path: \"" << m_path
+            << "\", decode mode: " << decodeMode << " ("
+            << (decodeMode == DecodeAtOnce ? "DecodeAtOnce" : "DecodeThreaded")
+            << ")" << endl;
+    
     m_channelCount = 0;
     m_fileRate = 0;
     m_fileSize = 0;
@@ -143,11 +148,11 @@
             usleep(10);
         }
         
-        cerr << "MP3FileReader ctor: exiting with file rate = " << m_fileRate << endl;
+        SVDEBUG << "MP3FileReader ctor: exiting with file rate = " << m_fileRate << endl;
     }
 
     if (m_error != "") {
-        cerr << "MP3FileReader::MP3FileReader(\"" << m_path << "\"): ERROR: " << m_error << endl;
+        SVDEBUG << "MP3FileReader::MP3FileReader(\"" << m_path << "\"): ERROR: " << m_error << endl;
     }
 }
 
@@ -182,9 +187,7 @@
     
     id3_tag *tag = id3_file_tag(file);
     if (!tag) {
-#ifdef DEBUG_ID3TAG
-        cerr << "MP3FileReader::loadTags: No ID3 tag found" << endl;
-#endif
+        SVDEBUG << "MP3FileReader::loadTags: No ID3 tag found" << endl;
         id3_file_close(file);
         return;
     }
@@ -205,10 +208,8 @@
     id3_file_close(file);
 
 #else
-#ifdef DEBUG_ID3TAG
-    cerr << "MP3FileReader::loadTags: ID3 tag support not compiled in"
-              << endl;
-#endif
+    SVDEBUG << "MP3FileReader::loadTags: ID3 tag support not compiled in"
+            << endl;
 #endif
 }
 
@@ -433,15 +434,20 @@
 }
 
 enum mad_flow
-MP3FileReader::error(void * /* dp */,
-		     struct mad_stream * /* stream */,
+MP3FileReader::error(void *dp,
+		     struct mad_stream *stream,
 		     struct mad_frame *)
 {
-//    DecoderData *data = (DecoderData *)dp;
-
-//    fprintf(stderr, "decoding error 0x%04x (%s) at byte offset %lu\n",
-//	    stream->error, mad_stream_errorstr(stream),
-//	    (unsigned long)(stream->this_frame - data->start));
+    static bool errorShown = false;
+    
+    if (!errorShown) {
+        DecoderData *data = (DecoderData *)dp;
+        fprintf(stderr, "Warning: MP3 decoding error 0x%04x (%s) at byte offset %lu\n",
+                stream->error, mad_stream_errorstr(stream),
+                (unsigned long)(stream->this_frame - data->start));
+        fprintf(stderr, "(Suppressing any further errors of this sort)\n");
+        errorShown = true;
+    }
 
     return MAD_FLOW_CONTINUE;
 }
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/OggVorbisFileReader.cpp
--- a/data/fileio/OggVorbisFileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/OggVorbisFileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -48,6 +48,11 @@
     m_completion(0),
     m_decodeThread(0)
 {
+    SVDEBUG << "OggVorbisFileReader: local path: \"" << m_path
+            << "\", decode mode: " << decodeMode << " ("
+            << (decodeMode == DecodeAtOnce ? "DecodeAtOnce" : "DecodeThreaded")
+            << ")" << endl;
+
     m_channelCount = 0;
     m_fileRate = 0;
 
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/QuickTimeFileReader.cpp
--- a/data/fileio/QuickTimeFileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/QuickTimeFileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -62,13 +62,16 @@
     m_completion(0),
     m_decodeThread(0)
 {
+    SVDEBUG << "QuickTimeFileReader: local path: \"" << m_path
+            << "\", decode mode: " << decodeMode << " ("
+            << (decodeMode == DecodeAtOnce ? "DecodeAtOnce" : "DecodeThreaded")
+            << ")" << endl;
+
     m_channelCount = 0;
     m_fileRate = 0;
 
     Profiler profiler("QuickTimeFileReader::QuickTimeFileReader", true);
 
-SVDEBUG << "QuickTimeFileReader: path is \"" << m_path << "\"" << endl;
-
     long QTversion;
 
 #ifdef WIN32
diff -r 0be27c989c1d -r 0a9193dc136b data/fileio/WavFileReader.cpp
--- a/data/fileio/WavFileReader.cpp	Tue Nov 22 16:40:28 2016 +0000
+++ b/data/fileio/WavFileReader.cpp	Tue Nov 22 16:40:41 2016 +0000
@@ -43,9 +43,9 @@
     m_file = sf_open(m_path.toLocal8Bit(), SFM_READ, &m_fileInfo);
 
     if (!m_file || (!fileUpdating && m_fileInfo.channels <= 0)) {
-	cerr << "WavFileReader::initialize: Failed to open file at \""
-                  << m_path << "\" ("
-		  << sf_strerror(m_file) << ")" << endl;
+	SVDEBUG << "WavFileReader::initialize: Failed to open file at \""
+                << m_path << "\" ("
+                << sf_strerror(m_file) << ")" << endl;
 
 	if (m_file) {
 	    m_error = QString("Couldn't load audio file '%1':\n%2")
@@ -84,7 +84,7 @@
         }
     }
 
-//    cerr << "WavFileReader: Filename " << m_path << ", frame count " << m_frameCount << ", channel count " << m_channelCount << ", sample rate " << m_sampleRate << ", format " << m_fileInfo.format << ", seekable " << m_fileInfo.seekable << " adjusted to " << m_seekable << endl;
+    SVDEBUG << "WavFileReader: Filename " << m_path << ", frame count " << m_frameCount << ", channel count " << m_channelCount << ", sample rate " << m_sampleRate << ", format " << m_fileInfo.format << ", seekable " << m_fileInfo.seekable << " adjusted to " << m_seekable << endl;
 }
 
 WavFileReader::~WavFileReader()
@@ -103,8 +103,8 @@
         sf_close(m_file);
         m_file = sf_open(m_path.toLocal8Bit(), SFM_READ, &m_fileInfo);
         if (!m_file || m_fileInfo.channels <= 0) {
-            cerr << "WavFileReader::updateFrameCount: Failed to open file at \"" << m_path << "\" ("
-                      << sf_strerror(m_file) << ")" << endl;
+            SVDEBUG << "WavFileReader::updateFrameCount: Failed to open file at \"" << m_path << "\" ("
+                    << sf_strerror(m_file) << ")" << endl;
         }
     }
 
@@ -118,7 +118,6 @@
     }
 
     if (m_frameCount != prevCount) {
-//        cerr << "frameCountChanged" << endl;
         emit frameCountChanged();
     }
 }