diff --git a/system/logging/AbstractAppender.cfc b/system/logging/AbstractAppender.cfc
index b81c0a0a8..170cb758c 100644
--- a/system/logging/AbstractAppender.cfc
+++ b/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 drainQueue() 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 drainQueue() 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
*
diff --git a/system/logging/appenders/FileAppender.cfc b/system/logging/appenders/FileAppender.cfc
index 84d940158..130fdfa58 100644
--- a/system/logging/appenders/FileAppender.cfc
+++ b/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
+ * preProcessQueue() 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.
*/
diff --git a/tests/specs/logging/appenders/FileAppenderTest.cfc b/tests/specs/logging/appenders/FileAppenderTest.cfc
index 8534bfcc5..afc53ca0e 100755
--- a/tests/specs/logging/appenders/FileAppenderTest.cfc
+++ b/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
}
}
diff --git a/tests/specs/logging/appenders/QueueTestFileAppender.cfc b/tests/specs/logging/appenders/QueueTestFileAppender.cfc
new file mode 100644
index 000000000..d94253025
--- /dev/null
+++ b/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()
+ }
+
+}