Cflog stops writing to files (was: First cflog entry stops writing for first file)

dev support
1

Using cflog works for the first entry and file, then stops writing to the first file.
Other (2nd/3rd) cflog files are unaffected.

I’m sure I’m losing my mind … sounded like LDEV-3710 (I believe the linked issue was mentioned as fixed in the snapshot. This issue is still happening in the latest stable / snapshot)

This is the test code

<cfloop from="1" to="2" index="idx">
	<cflog type="information" file="testone" text="testone #idx# - Lucee Version: #server.lucee.version#" />
	<!--- Currently: one entry. Subsequent requests to this file are not logged until restart.
		Expected: two entries per execution
		Status: failing
	 --->


	<cflog type="information" file="testtwo" text="testtwo #idx# - Lucee Version: #server.lucee.version#" />
	<!--- Currently: two entries
		Expected: two entries
		Status: passing
	 --->
</cfloop>

Don’t forget to tell us about your stack!

OS: Windows 10
Java Version: 11.0.7
Tomcat Version: 9.0.35
Lucee Version: 5.3.9.133 / 5.3.9.134-SNAPSHOT

2

After leaving Lucee running on 5.3.9.134-SNAPSHOT for a few hours, I’m not able to write to either of the testone / testtwo log files.

Updated code (added two more log files and output below):

<cfloop from="1" to="2" index="idx">
	<cflog type="information" file="testone" text="testone #idx# - Lucee Version: #server.lucee.version#" />
	<!--- Currently: one entry. Subsequent requests to this file are not logged until restart.
				Expected: two entries per execution
				Status: failing
	--->
	<cflog type="information" file="testtwo" text="testtwo #idx# - Lucee Version: #server.lucee.version#" />
	<!--- Currently: two entries, next day, zero entries
				Expected: two entries
				Status: passing initially, next day failing
	--->

	<!--- Added logging after several hours of uptime --->
	<cflog type="information" file="nextdayone" text="nextdayone #idx# - Lucee Version: #server.lucee.version#" />
	<!--- same initial behavior as testone --->
	<cflog type="information" file="nextdaytwo" text="nextdaytwo #idx# - Lucee Version: #server.lucee.version#" />
	<!--- same initial behavior as testtwo --->
</cfloop>

nextdayone.log output:

"Severity","ThreadID","Date","Time","Application","Message"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:30","myApplication","nextdayone 1 - Lucee Version: 5.3.9.134-SNAPSHOT"

nextdaytwo.log output:

"Severity","ThreadID","Date","Time","Application","Message"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:30","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:30","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-3","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-3","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-7","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-7","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-2","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-2","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-1","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-1","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-10","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-10","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-9","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-9","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-2","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-2","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-1","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-1","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-5","05/03/2022","07:06:33","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-5","05/03/2022","07:06:33","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:34","myApplication","nextdaytwo 1 - Lucee Version: 5.3.9.134-SNAPSHOT"
"INFO","ajp-nio-127.0.0.1-8009-exec-6","05/03/2022","07:06:34","myApplication","nextdaytwo 2 - Lucee Version: 5.3.9.134-SNAPSHOT"
3

bug filed [LDEV-3978] - Lucee

2 Likes
4

Glad there is a bug filed for this, now.
I thought I was going nuts - with inconsistent log entries!

1 Like
5

Will mark resolved for those bumping into this / losing their minds.

I can confirm 5.3.9.137-SNAPSHOT and later resolves this issue.

2 Likes