COLDBOX-1467 FileAppender writes queued lines several times on Adobe ColdFusion

system/logging/AbstractAppender.cfc

@@ -476,6 +476,9 @@ component accessors="true" {
 	/**
 	 *  Fired before the queue is processed within the log listener thread
 	 *
+	 * The queue argument may be a copy (Adobe ColdFusion passes arrays by value), so only read it.
+	 * Use <code>drainQueue()</code> to remove entries from the appender's queue.
+	 *
 	 * @queue        The queue itself
 	 * @queueContext A struct of data attached to this processing queue thread
 	 */
@@ -485,6 +488,9 @@ component accessors="true" {
 	/**
 	 *  Fired after the queue is processed within the log listener thread
 	 *
+	 * The queue argument may be a copy (Adobe ColdFusion passes arrays by value), so only read it.
+	 * Use <code>drainQueue()</code> to remove entries from the appender's queue.
+	 *
 	 * @queue        The queue itself
 	 * @queueContext A struct of data attached to this processing queue thread
 	 */
@@ -504,6 +510,8 @@ component accessors="true" {
 	 * Processes a queue element to a destination
 	 * This method is called by the log listeners asynchronously.
 	 *
+	 * The queue argument may be a copy (Adobe ColdFusion passes arrays by value), so only read it.
+	 *
 	 * @data         The data element the queue needs processing
 	 * @queueContext The queue context in process
 	 * @queue        The queue itself
@@ -561,6 +569,27 @@ component accessors="true" {
 		return this;
 	}
 
+	/**
+	 * Removes and returns the entries queued so far. Anything queued while this runs stays for the
+	 * next pass. It works on the appender's own queue, not on a queue argument, so it is safe
+	 * whether the engine passes arrays by value (Adobe ColdFusion) or by reference.
+	 *
+	 * @return The removed entries, in queue order
+	 */
+	private array function drainQueue(){
+		// Always go through variables: assigning the queue to a local copies it on Adobe ColdFusion
+		var count = variables.logListener.queue.len()
+		if ( !count ) {
+			return []
+		}
+		var entries = variables.logListener.queue.slice( 1, count )
+		// Remove exactly what was read instead of clear(), so entries queued meanwhile are kept
+		for ( var i = 1; i <= count; i++ ) {
+			variables.logListener.queue.deleteAt( 1 )
+		}
+		return entries
+	}
+
 	/**
 	 * A functional locking wrapper for the appender which uses it's internal hash and name as the lock name
 	 *

system/logging/appenders/FileAppender.cfc

@@ -171,29 +171,45 @@ component accessors="true" extends="coldbox.system.logging.AbstractAppender" {
 	 * We do this here instead of processing the queue one by one since we can accelerate it
 	 * via toList() operations and fileWriteLine() operations.
 	 *
+	 * The queue argument is not used: it may be a copy (Adobe ColdFusion passes arrays by value),
+	 * so the appender drains its own queue instead.
+	 *
 	 * @queue        The queue itself
 	 * @queueContext A struct of data attached to this processing queue thread
 	 */
 	function preProcessQueue( required queue, required struct queueContext ){
-		if ( arguments.queue.len() ) {
+		if ( variables.logListener.queue.len() ) {
 			variables.lock( () => {
-				if ( queue.len() ) {
-					var oFile = fileOpen(
-						variables.logFullPath,
-						"append",
-						this.getProperty( "fileEncoding" )
-					);
-					try {
-						fileWriteLine( oFile, queue.toList( chr( 13 ) & chr( 10 ) ) );
-					} finally {
-						fileClose( oFile );
-						queue.clear();
-					}
+				var lines = drainQueue()
+				if ( lines.len() ) {
+					appendLines( lines )
 				}
 			} );
 		}
 	}
 
+	/**
+	 * Writes an entry the log listener dequeued itself, one that was queued after
+	 * <code>preProcessQueue()</code> drained the queue, to the log file
+	 *
+	 * @data         The log line to write
+	 * @queueContext The queue context in process
+	 * @queue        The queue itself
+	 *
+	 * @return The appender
+	 */
+	function processQueueElement(
+		required data,
+		required queueContext,
+		required queue
+	){
+		var line = arguments.data
+		variables.lock( () => {
+			appendLines( [ line ] )
+		} )
+		return this
+	}
+
 	/**
 	 * Fired once the listener starts queue processing. This only runs
 	 * once per listener thread.  Remember that the listener thread is
@@ -209,6 +225,24 @@ component accessors="true" extends="coldbox.system.logging.AbstractAppender" {
 
 	/************************************ PRIVATE ************************************/
 
+	/**
+	 * Appends lines to the log file in one write. Callers hold the appender lock.
+	 *
+	 * @lines The log lines to write
+	 */
+	private function appendLines( required array lines ){
+		var oFile = fileOpen(
+			variables.logFullPath,
+			"append",
+			this.getProperty( "fileEncoding" )
+		)
+		try {
+			fileWriteLine( oFile, arguments.lines.toList( chr( 13 ) & chr( 10 ) ) )
+		} finally {
+			fileClose( oFile )
+		}
+	}
+
 	/**
 	 * Ensures the log directory.
 	 */

tests/specs/logging/appenders/FileAppenderTest.cfc

@@ -41,7 +41,8 @@ component extends="coldbox.system.testing.BaseModelTest" {
 		variables.logBox       = new coldbox.system.logging.LogBox()
 		variables.fileappender = createMock( "coldbox.system.logging.appenders.FileAppender" ).setLogBox( logBox )
 
-		variables.fileappender.init( "MyFileAppender", props )
+		// Own file name: RollingFileAppenderTest writes to MyFileAppender.log from its listener thread
+		variables.fileappender.init( "FileAppenderTest", props )
 
 		variables.loge = createMock( "coldbox.system.logging.LogEvent" )
 		variables.loge.init( "Unit Test Sample", 0, "", "UnitTest" )
@@ -73,10 +74,61 @@ component extends="coldbox.system.testing.BaseModelTest" {
 				writeDump( var = "Sleeping for 5 seconds waiting for log file...", output = "console" );
 				sleep( 5000 );
 
-				var content = fileRead( fileAppender.getLogFullPath() );
-				expect( content ).toInclude( "Unit Test Sample" );
+				var lines = writtenLines( fileAppender ).filter( ( line ) => line contains "Unit Test Sample" )
+				expect( lines.len() ).toBe( 6, "each message is written exactly once" )
 			} );
 		} );
+
+		describe( "File Appender queue", function(){
+			it( "writes each queued line once when the log listener drains the queue", function(){
+				var appender = newQueueAppender()
+				appender
+					.queueMessage( "one" )
+					.queueMessage( "two" )
+					.queueMessage( "three" )
+
+				appender.runLogListener()
+
+				expect( writtenLines( appender ) ).toBe( [ "one", "two", "three" ] )
+				expect( appender.pending() ).toBe( 0, "the appender's own queue is drained" )
+			} );
+
+			it( "writes a line the listener pops itself to the file, not the console", function(){
+				var appender = newQueueAppender()
+
+				appender.processQueueElement( "popped", {}, [] )
+
+				expect( writtenLines( appender ) ).toBe( [ "popped" ] )
+			} );
+		} );
+	}
+
+	/**
+	 * A FileAppender with its own log file whose listener runs in the test thread
+	 */
+	private function newQueueAppender(){
+		var name     = "QueueSpec" & left( replace( createUUID(), "-", "", "all" ), 8 )
+		var appender = new tests.specs.logging.appenders.QueueTestFileAppender(
+			name       = name,
+			properties = {
+				filePath   : expandPath( "/tests/logs" ),
+				autoExpand : false
+			}
+		)
+		appender.setLogBox( variables.logBox )
+		appender.initLogLocation()
+		return appender
+	}
+
+	/**
+	 * The lines of an appender's log file after the header row
+	 *
+	 * @appender The file appender to read
+	 */
+	private array function writtenLines( required appender ){
+		var lines = fileRead( arguments.appender.getLogFullPath() ).listToArray( chr( 13 ) & chr( 10 ) )
+		lines.deleteAt( 1 )
+		return lines
 	}
 
 }

tests/specs/logging/appenders/QueueTestFileAppender.cfc

@@ -0,0 +1,30 @@
+/**
+ * Test appender for driving the FileAppender log listener in the test thread.
+ * queueMessage() only queues (no background listener is scheduled), and a direct
+ * runLogListener() call returns as soon as the queue is empty instead of idling.
+ */
+component extends="coldbox.system.logging.appenders.FileAppender" {
+
+	/**
+	 * Do not schedule a background listener, the spec calls runLogListener() itself.
+	 */
+	function startLogListener(){
+	}
+
+	/**
+	 * End the listener loop as soon as the queue is empty.
+	 *
+	 * @queueContext A struct of data attached to this processing queue thread
+	 */
+	function onLogListenerSleep( required struct queueContext ){
+		arguments.queueContext.maxIdle = 0
+	}
+
+	/**
+	 * How many entries are still waiting in the appender's own queue.
+	 */
+	numeric function pending(){
+		return variables.logListener.queue.len()
+	}
+
+}