From 9554e95bc6f1f823c3a530174b286c3c6c1d7484 Mon Sep 17 00:00:00 2001 From: David Levin Date: Mon, 19 Oct 2026 09:29:54 -0700 Subject: [PATCH 1/2] COLDBOX-1467 #resolve FileAppender writes queued lines several times on Adobe ColdFusion --- system/logging/AbstractAppender.cfc | 29 +++++++++ system/logging/appenders/FileAppender.cfc | 60 +++++++++++++++---- .../logging/appenders/FileAppenderTest.cfc | 55 ++++++++++++++++- .../appenders/QueueTestFileAppender.cfc | 30 ++++++++++ 4 files changed, 159 insertions(+), 15 deletions(-) create mode 100644 tests/specs/logging/appenders/QueueTestFileAppender.cfc 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..410c9990c 100755 --- a/tests/specs/logging/appenders/FileAppenderTest.cfc +++ b/tests/specs/logging/appenders/FileAppenderTest.cfc @@ -73,10 +73,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() + } + +} From ef91683ffb07978c009caa32e8c588a20bfc79ed Mon Sep 17 00:00:00 2001 From: David Levin Date: Mon, 19 Oct 2026 10:14:14 -0700 Subject: [PATCH 2/2] COLDBOX-1467 Give the FileAppender spec its own log file RollingFileAppenderTest writes to the same MyFileAppender.log from its listener thread, so when it ran first the exact line count saw its leftover lines. --- tests/specs/logging/appenders/FileAppenderTest.cfc | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tests/specs/logging/appenders/FileAppenderTest.cfc b/tests/specs/logging/appenders/FileAppenderTest.cfc index 410c9990c..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" )