clean up audio engine logging

2 files changed, 73 insertions, 67 deletions

diff --git a/indra/llaudio/llaudiodecodemgr.cpp b/indra/llaudio/llaudiodecodemgr.cpp
index 6c97a64ed7..8c31f8b4de 100755
--- a/indra/llaudio/llaudiodecodemgr.cpp
+++ b/indra/llaudio/llaudiodecodemgr.cpp
@@ -135,7 +135,7 @@ int vfs_seek(void *datasource, ogg_int64_t offset, int whence)
 		origin = -1;
 		break;
 	default:
-		llerrs << "Invalid whence argument to vfs_seek" << llendl;
+		LL_ERRS("AudioEngine") << "Invalid whence argument to vfs_seek" << LL_ENDL;
 		return -1;
 	}
 
@@ -197,12 +197,12 @@ BOOL LLVorbisDecodeState::initDecode()
 	vfs_callbacks.close_func = vfs_close;
 	vfs_callbacks.tell_func = vfs_tell;
 
-	//llinfos << "Initing decode from vfile: " << mUUID << llendl;
+	LL_DEBUGS("AudioEngine") << "Initing decode from vfile: " << mUUID << LL_ENDL;
 
 	mInFilep = new LLVFile(gVFS, mUUID, LLAssetType::AT_SOUND);
 	if (!mInFilep || !mInFilep->getSize())
 	{
-		llwarns << "unable to open vorbis source vfile for reading" << llendl;
+		LL_WARNS("AudioEngine") << "unable to open vorbis source vfile for reading" << LL_ENDL;
 		delete mInFilep;
 		mInFilep = NULL;
 		return FALSE;
@@ -211,7 +211,7 @@ BOOL LLVorbisDecodeState::initDecode()
 	int r = ov_open_callbacks(mInFilep, &mVF, NULL, 0, vfs_callbacks);
 	if(r < 0) 
 	{
-		llwarns << r << " Input to vorbis decode does not appear to be an Ogg bitstream: " << mUUID << llendl;
+		LL_WARNS("AudioEngine") << r << " Input to vorbis decode does not appear to be an Ogg bitstream: " << mUUID << LL_ENDL;
 		return(FALSE);
 	}
 	
@@ -229,36 +229,36 @@ BOOL LLVorbisDecodeState::initDecode()
 		if( vi->channels < 1 || vi->channels > LLVORBIS_CLIP_MAX_CHANNELS )
 		{
 			abort_decode = true;
-			llwarns << "Bad channel count: " << vi->channels << llendl;
+			LL_WARNS("AudioEngine") << "Bad channel count: " << vi->channels << LL_ENDL;
 		}
 	}
 	else // !vi
 	{
 		abort_decode = true;
-		llwarns << "No default bitstream found" << llendl;	
+		LL_WARNS("AudioEngine") << "No default bitstream found" << LL_ENDL;	
 	}
 	
 	if( (size_t)sample_count > LLVORBIS_CLIP_REJECT_SAMPLES ||
 	    (size_t)sample_count <= 0)
 	{
 		abort_decode = true;
-		llwarns << "Illegal sample count: " << sample_count << llendl;
+		LL_WARNS("AudioEngine") << "Illegal sample count: " << sample_count << LL_ENDL;
 	}
 	
 	if( size_guess > LLVORBIS_CLIP_REJECT_SIZE ||
 	    size_guess < 0)
 	{
 		abort_decode = true;
-		llwarns << "Illegal sample size: " << size_guess << llendl;
+		LL_WARNS("AudioEngine") << "Illegal sample size: " << size_guess << LL_ENDL;
 	}
 	
 	if( abort_decode )
 	{
-		llwarns << "Canceling initDecode. Bad asset: " << mUUID << llendl;
+		LL_WARNS("AudioEngine") << "Canceling initDecode. Bad asset: " << mUUID << LL_ENDL;
 		vorbis_comment* comment = ov_comment(&mVF,-1);
 		if (comment && comment->vendor)
 		{
-			llwarns << "Bad asset encoded by: " << comment->vendor << llendl;
+			LL_WARNS("AudioEngine") << "Bad asset encoded by: " << comment->vendor << LL_ENDL;
 		}
 		delete mInFilep;
 		mInFilep = NULL;
@@ -359,12 +359,12 @@ BOOL LLVorbisDecodeState::decodeSection()
 {
 	if (!mInFilep)
 	{
-		llwarns << "No VFS file to decode in vorbis!" << llendl;
+		LL_WARNS("AudioEngine") << "No VFS file to decode in vorbis!" << LL_ENDL;
 		return TRUE;
 	}
 	if (mDone)
 	{
-// 		llwarns << "Already done with decode, aborting!" << llendl;
+// 		LL_WARNS("AudioEngine") << "Already done with decode, aborting!" << LL_ENDL;
 		return TRUE;
 	}
 	char pcmout[4096];	/*Flawfinder: ignore*/
@@ -377,14 +377,14 @@ BOOL LLVorbisDecodeState::decodeSection()
 		eof = TRUE;
 		mDone = TRUE;
 		mValid = TRUE;
-//			llinfos << "Vorbis EOF" << llendl;
+//			LL_INFOS("AudioEngine") << "Vorbis EOF" << LL_ENDL;
 	}
 	else if (ret < 0)
 	{
 		/* error in the stream.  Not a problem, just reporting it in
 		   case we (the app) cares.  In this case, we don't. */
 
-		llwarns << "BAD vorbis decode in decodeSection." << llendl;
+		LL_WARNS("AudioEngine") << "BAD vorbis decode in decodeSection." << LL_ENDL;
 
 		mValid = FALSE;
 		mDone = TRUE;
@@ -393,7 +393,7 @@ BOOL LLVorbisDecodeState::decodeSection()
 	}
 	else
 	{
-//			llinfos << "Vorbis read " << ret << "bytes" << llendl;
+//			LL_INFOS("AudioEngine") << "Vorbis read " << ret << "bytes" << LL_ENDL;
 		/* we don't bother dealing with sample rate changes, etc, but.
 		   you'll have to*/
 		std::copy(pcmout, pcmout+ret, std::back_inserter(mWAVBuffer));
@@ -405,7 +405,7 @@ BOOL LLVorbisDecodeState::finishDecode()
 {
 	if (!isValid())
 	{
-		llwarns << "Bogus vorbis decode state for " << getUUID() << ", aborting!" << llendl;
+		LL_WARNS("AudioEngine") << "Bogus vorbis decode state for " << getUUID() << ", aborting!" << LL_ENDL;
 		return TRUE; // We've finished
 	}
 
@@ -480,7 +480,7 @@ BOOL LLVorbisDecodeState::finishDecode()
 
 		if (36 == data_length)
 		{
-			llwarns << "BAD Vorbis decode in finishDecode!" << llendl;
+			LL_WARNS("AudioEngine") << "BAD Vorbis decode in finishDecode!" << LL_ENDL;
 			mValid = FALSE;
 			return TRUE; // we've finished
 		}
@@ -497,7 +497,7 @@ BOOL LLVorbisDecodeState::finishDecode()
 		{
 			if (mBytesRead == 0)
 			{
-				llwarns << "Unable to write file in LLVorbisDecodeState::finishDecode" << llendl;
+				LL_WARNS("AudioEngine") << "Unable to write file in LLVorbisDecodeState::finishDecode" << LL_ENDL;
 				mValid = FALSE;
 				return TRUE; // we've finished
 			}
@@ -515,7 +515,7 @@ BOOL LLVorbisDecodeState::finishDecode()
 	LLVFile output(gVFS, mUUID, LLAssetType::AT_SOUND_WAV);
 	output.write(&mWAVBuffer[0], mWAVBuffer.size());
 #endif
-	//llinfos << "Finished decode for " << getUUID() << llendl;
+	LL_DEBUGS("AudioEngine") << "Finished decode for " << getUUID() << LL_ENDL;
 
 	return TRUE;
 }
@@ -524,7 +524,7 @@ void LLVorbisDecodeState::flushBadFile()
 {
 	if (mInFilep)
 	{
-		llwarns << "Flushing bad vorbis file from VFS for " << mUUID << llendl;
+		LL_WARNS("AudioEngine") << "Flushing bad vorbis file from VFS for " << mUUID << LL_ENDL;
 		mInFilep->remove();
 	}
 }
@@ -568,7 +568,7 @@ void LLAudioDecodeMgr::Impl::processQueue(const F32 num_secs)
 			if (mCurrentDecodep->isDone() && !mCurrentDecodep->isValid())
 			{
 				// We had an error when decoding, abort.
-				llwarns << mCurrentDecodep->getUUID() << " has invalid vorbis data, aborting decode" << llendl;
+				LL_WARNS("AudioEngine") << mCurrentDecodep->getUUID() << " has invalid vorbis data, aborting decode" << LL_ENDL;
 				mCurrentDecodep->flushBadFile();
 				LLAudioData *adp = gAudiop->getAudioData(mCurrentDecodep->getUUID());
 				adp->setHasValidData(false);
@@ -590,7 +590,7 @@ void LLAudioDecodeMgr::Impl::processQueue(const F32 num_secs)
 					LLAudioData *adp = gAudiop->getAudioData(mCurrentDecodep->getUUID());
 					if (!adp)
 					{
-						llwarns << "Missing LLAudioData for decode of " << mCurrentDecodep->getUUID() << llendl;
+						LL_WARNS("AudioEngine") << "Missing LLAudioData for decode of " << mCurrentDecodep->getUUID() << LL_ENDL;
 					}
 					else if (mCurrentDecodep->isValid() && mCurrentDecodep->isDone())
 					{
@@ -601,12 +601,12 @@ void LLAudioDecodeMgr::Impl::processQueue(const F32 num_secs)
 						// At this point, we could see if anyone needs this sound immediately, but
 						// I'm not sure that there's a reason to - we need to poll all of the playing
 						// sounds anyway.
-						//llinfos << "Finished the vorbis decode, now what?" << llendl;
+						//LL_INFOS("AudioEngine") << "Finished the vorbis decode, now what?" << LL_ENDL;
 					}
 					else
 					{
 						adp->setHasCompletedDecode(true);
-						llinfos << "Vorbis decode failed for " << mCurrentDecodep->getUUID() << llendl;
+						LL_INFOS("AudioEngine") << "Vorbis decode failed for " << mCurrentDecodep->getUUID() << LL_ENDL;
 					}
 					mCurrentDecodep = NULL;
 				}
@@ -631,7 +631,7 @@ void LLAudioDecodeMgr::Impl::processQueue(const F32 num_secs)
 					continue;
 				}
 
-				lldebugs << "Decoding " << uuid << " from audio queue!" << llendl;
+				lldebugs << "Decoding " << uuid << " from audio queue!" << LL_ENDL;
 
 				std::string uuid_str;
 				std::string d_path;
@@ -674,19 +674,19 @@ BOOL LLAudioDecodeMgr::addDecodeRequest(const LLUUID &uuid)
 	if (gAudiop->hasDecodedFile(uuid))
 	{
 		// Already have a decoded version, don't need to decode it.
-		//llinfos << "addDecodeRequest for " << uuid << " has decoded file already" << llendl;
+		LL_DEBUGS("AudioEngine") << "addDecodeRequest for " << uuid << " has decoded file already" << LL_ENDL;
 		return TRUE;
 	}
 
 	if (gAssetStorage->hasLocalAsset(uuid, LLAssetType::AT_SOUND))
 	{
 		// Just put it on the decode queue.
-		//llinfos << "addDecodeRequest for " << uuid << " has local asset file already" << llendl;
+		LL_DEBUGS("AudioEngine") << "addDecodeRequest for " << uuid << " has local asset file already" << LL_ENDL;
 		mImpl->mDecodeQueue.push(uuid);
 		return TRUE;
 	}
 
-	//llinfos << "addDecodeRequest for " << uuid << " no file available" << llendl;
+	LL_DEBUGS("AudioEngine") << "addDecodeRequest for " << uuid << " no file available" << LL_ENDL;
 	return FALSE;
 }
 
diff --git a/indra/llaudio/llaudioengine.cpp b/indra/llaudio/llaudioengine.cpp
index 06e752cf34..ca614f5395 100755
--- a/indra/llaudio/llaudioengine.cpp
+++ b/indra/llaudio/llaudioengine.cpp
@@ -123,7 +123,7 @@ bool LLAudioEngine::init(const S32 num_channels, void* userdata)
 	// Initialize the decode manager
 	gAudioDecodeMgrp = new LLAudioDecodeMgr;
 
-	llinfos << "LLAudioEngine::init() AudioEngine successfully initialized" << llendl;
+	LL_INFOS("AudioEngine") << "LLAudioEngine::init() AudioEngine successfully initialized" << LL_ENDL;
 
 	return true;
 }
@@ -308,7 +308,7 @@ void LLAudioEngine::idle(F32 max_decode_time)
 		LLAudioChannel *channelp = getFreeChannel(max_priority);
 		if (channelp)
 		{
-			//llinfos << "Replacing source in channel due to priority!" << llendl;
+			LL_DEBUGS("AudioEngine") << "Replacing source in channel due to priority!" << LL_ENDL;
 			max_sourcep->setChannel(channelp);
 			channelp->setSource(max_sourcep);
 			if (max_sourcep->isSyncSlave())
@@ -479,7 +479,7 @@ void LLAudioEngine::idle(F32 max_decode_time)
 		{
 			if (!mBuffers[i]->mInUse && mBuffers[i]->mLastUseTimer.getElapsedTimeF32() > 30.f)
 			{
-				//llinfos << "Flushing unused buffer!" << llendl;
+				LL_DEBUGS("AudioEngine") << "Flushing unused buffer!" << LL_ENDL;
 				mBuffers[i]->mAudioDatap->mBufferp = NULL;
 				delete mBuffers[i];
 				mBuffers[i] = NULL;
@@ -591,8 +591,8 @@ LLAudioBuffer * LLAudioEngine::getFreeBuffer()
 
 	if (buffer_id >= 0)
 	{
-		lldebugs << "Taking over unused buffer " << buffer_id << llendl;
-		//llinfos << "Flushing unused buffer!" << llendl;
+		lldebugs << "Taking over unused buffer " << buffer_id << LL_ENDL;
+		LL_DEBUGS("AudioEngine") << "Flushing unused buffer!" << LL_ENDL;
 		mBuffers[buffer_id]->mAudioDatap->mBufferp = NULL;
 		delete mBuffers[buffer_id];
 		mBuffers[buffer_id] = createBuffer();
@@ -673,6 +673,8 @@ void LLAudioEngine::cleanupBuffer(LLAudioBuffer *bufferp)
 
 bool LLAudioEngine::preloadSound(const LLUUID &uuid)
 {
+	LL_DEBUGS("AudioEngine")<<"( "<<uuid<<" )"<<LL_ENDL;
+	
 	gAudiop->getAudioData(uuid);	// We don't care about the return value, this is just to make sure
 									// that we have an entry, which will mean that the audio engine knows about this
 
@@ -684,7 +686,7 @@ bool LLAudioEngine::preloadSound(const LLUUID &uuid)
 
 	// At some point we need to have the audio/asset system check the static VFS
 	// before it goes off and fetches stuff from the server.
-	//llwarns << "Used internal preload for non-local sound" << llendl;
+	LL_DEBUGS("AudioEngine") << "Used internal preload for non-local sound "<< uuid << LL_ENDL;
 	return false;
 }
 
@@ -815,7 +817,7 @@ void LLAudioEngine::triggerSound(const LLUUID &audio_uuid, const LLUUID& owner_i
 								 const S32 type, const LLVector3d &pos_global)
 {
 	// Create a new source (since this can't be associated with an existing source.
-	//llinfos << "Localized: " << audio_uuid << llendl;
+	LL_DEBUGS("AudioEngine") << "Localized: " << audio_uuid << LL_ENDL;
 
 	if (mMuted)
 	{
@@ -982,11 +984,14 @@ void LLAudioEngine::cleanupAudioSource(LLAudioSource *asp)
 	iter = mAllSources.find(asp->getID());
 	if (iter == mAllSources.end())
 	{
-		llwarns << "Cleaning up unknown audio source!" << llendl;
-		return;
+		LL_WARNS("AudioEngine") << "Cleaning up unknown audio source!" << LL_ENDL;
+	}
+	else
+	{
+		LL_DEBUGS("AudioEngine") << "Cleaning up audio sources for "<< asp->getID() <<LL_ENDL;
+		delete asp;
+		mAllSources.erase(iter);
 	}
-	delete asp;
-	mAllSources.erase(iter);
 }
 
 
@@ -1013,16 +1018,18 @@ bool LLAudioEngine::hasDecodedFile(const LLUUID &uuid)
 bool LLAudioEngine::hasLocalFile(const LLUUID &uuid)
 {
 	// See if it's in the VFS.
-	return gVFS->getExists(uuid, LLAssetType::AT_SOUND);
+	bool have_local = gVFS->getExists(uuid, LLAssetType::AT_SOUND);
+	LL_DEBUGS("AudioEngine") << "sound uuid "<<uuid<<" exists in VFS"<<LL_ENDL;
+	return have_local;
 }
 
 
 void LLAudioEngine::startNextTransfer()
 {
-	//llinfos << "LLAudioEngine::startNextTransfer()" << llendl;
+	//LL_DEBUGS("AudioEngine") << "LLAudioEngine::startNextTransfer()" << LL_ENDL;
 	if (mCurrentTransfer.notNull() || getMuted())
 	{
-		//llinfos << "Transfer in progress, aborting" << llendl;
+		//LL_DEBUGS("AudioEngine") << "Transfer in progress, aborting" << LL_ENDL;
 		return;
 	}
 
@@ -1203,7 +1210,7 @@ void LLAudioEngine::startNextTransfer()
 
 	if (asset_id.notNull())
 	{
-		llinfos << "Getting asset data for: " << asset_id << llendl;
+		LL_INFOS("AudioEngine") << "Getting audio asset data for: " << asset_id << LL_ENDL;
 		gAudiop->mCurrentTransfer = asset_id;
 		gAudiop->mCurrentTransferTimer.reset();
 		gAssetStorage->getAssetData(asset_id, LLAssetType::AT_SOUND,
@@ -1211,7 +1218,7 @@ void LLAudioEngine::startNextTransfer()
 	}
 	else
 	{
-		//llinfos << "No pending transfers?" << llendl;
+		//LL_DEBUGS("AudioEngine") << "No pending transfers?" << LL_ENDL;
 	}
 }
 
@@ -1221,7 +1228,7 @@ void LLAudioEngine::assetCallback(LLVFS *vfs, const LLUUID &uuid, LLAssetType::E
 {
 	if (result_code)
 	{
-		llinfos << "Boom, error in audio file transfer: " << LLAssetStorage::getErrorString( result_code ) << " (" << result_code << ")" << llendl;
+		LL_INFOS("AudioEngine") << "Boom, error in audio file transfer: " << LLAssetStorage::getErrorString( result_code ) << " (" << result_code << ")" << LL_ENDL;
 		// Need to mark data as bad to avoid constant rerequests.
 		LLAudioData *adp = gAudiop->getAudioData(uuid);
 		if (adp)
@@ -1238,11 +1245,11 @@ void LLAudioEngine::assetCallback(LLVFS *vfs, const LLUUID &uuid, LLAssetType::E
 		if (!adp)
         {
 			// Should never happen
-			llwarns << "Got asset callback without audio data for " << uuid << llendl;
+			LL_WARNS("AudioEngine") << "Got asset callback without audio data for " << uuid << LL_ENDL;
         }
 		else
 		{
-			// llinfos << "Got asset callback with good audio data for " << uuid << ", making decode request" << llendl;
+			LL_DEBUGS("AudioEngine") << "Got asset callback with good audio data for " << uuid << ", making decode request" << LL_ENDL;
 			adp->setHasValidData(true);
 		    adp->setHasLocalData(true);
 		    gAudioDecodeMgrp->addDecodeRequest(uuid);
@@ -1321,7 +1328,7 @@ void LLAudioSource::update()
 			}
 			else if (adp->hasCompletedDecode())		// Only mark corrupted after decode is done
 			{
-				llwarns << "Marking LLAudioSource corrupted for " << adp->getID() << llendl;
+				LL_WARNS("AudioEngine") << "Marking LLAudioSource corrupted for " << adp->getID() << LL_ENDL;
 				mCorrupted = true ;
 			}
 		}
@@ -1357,7 +1364,6 @@ bool LLAudioSource::setupChannel()
 	if (!adp->getBuffer())
 	{
 		// We're not ready to play back the sound yet, so don't try and allocate a channel for it.
-		//llwarns << "Aborting, no buffer" << llendl;
 		return false;
 	}
 
@@ -1375,7 +1381,7 @@ bool LLAudioSource::setupChannel()
 		// Ugh, we don't have any free channels.
 		// Now we have to reprioritize.
 		// For now, just don't play the sound.
-		//llwarns << "Aborting, no free channels" << llendl;
+		//llwarns << "Aborting, no free channels" << LL_ENDL;
 		return false;
 	}
 
@@ -1474,7 +1480,7 @@ bool LLAudioSource::isDone() const
 		{
 			// We don't have a channel assigned, and it's been
 			// over 15 seconds since we tried to play it.  Don't bother.
-			//llinfos << "No channel assigned, source is done" << llendl;
+			LL_DEBUGS("AudioEngine") << "No channel assigned, source is done" << LL_ENDL;
 			return true;
 		}
 		else
@@ -1640,7 +1646,7 @@ LLAudioChannel::LLAudioChannel() :
 LLAudioChannel::~LLAudioChannel()
 {
 	// Need to disconnect any sources which are using this channel.
-	//llinfos << "Cleaning up audio channel" << llendl;
+	LL_DEBUGS("AudioEngine") << "Cleaning up audio channel" << LL_ENDL;
 	if (mCurrentSourcep)
 	{
 		mCurrentSourcep->setChannel(NULL);
@@ -1651,29 +1657,29 @@ LLAudioChannel::~LLAudioChannel()
 
 void LLAudioChannel::setSource(LLAudioSource *sourcep)
 {
-	//llinfos << this << ": setSource(" << sourcep << ")" << llendl;
-
 	if (!sourcep)
 	{
 		// Clearing the source for this channel, don't need to do anything.
-		//llinfos << "Clearing source for channel" << llendl;
+		LL_DEBUGS("AudioEngine") << "Clearing source" << ( mCurrentSourcep ? mCurrentSourcep->getID() : LLUUID::null ) << LL_ENDL;
 		cleanup();
 		mCurrentSourcep = NULL;
 		mWaiting = false;
-		return;
 	}
-
-	if (sourcep == mCurrentSourcep)
+	else
 	{
-		// Don't reallocate the channel, this will make FMOD goofy.
-		//llinfos << "Calling setSource with same source!" << llendl;
-	}
-
-	mCurrentSourcep = sourcep;
+		LL_DEBUGS("AudioEngine") << "( id: " << sourcep->getID() << ")" << LL_ENDL;
 
+		if (sourcep == mCurrentSourcep)
+		{
+			// Don't reallocate the channel, this will make FMOD goofy.
+			//LL_DEBUGS("AudioEngine") << "Calling setSource with same source!" << LL_ENDL;
+		}
 
-	updateBuffer();
-	update3DPosition();
+		mCurrentSourcep = sourcep;
+		
+		updateBuffer();
+		update3DPosition();
+	}
 }
 
 
@@ -1768,7 +1774,7 @@ bool LLAudioData::load()
 	if (mBufferp)
 	{
 		// We already have this sound in a buffer, don't do anything.
-		llinfos << "Already have a buffer for this sound, don't bother loading!" << llendl;
+		LL_INFOS("AudioEngine") << "Already have a buffer for this sound, don't bother loading!" << LL_ENDL;
 		return true;
 	}
 	
@@ -1776,7 +1782,7 @@ bool LLAudioData::load()
 	if (!mBufferp)
 	{
 		// No free buffers, abort.
-		llinfos << "Not able to allocate a new audio buffer, aborting." << llendl;
+		LL_INFOS("AudioEngine") << "Not able to allocate a new audio buffer, aborting." << LL_ENDL;
 		return true;
 	}