Lucee is sometimes logging to the wrong site

stillnet · November 1, 2022, 4:22pm

Hi, we’re seeing an issue where Lucee occasionally logs to the wrong site. We have 5 sites setup on a server. We use Apache as web server in front of Lucee/Tomcat. The web roots are located in C:\Inetpub\wwwroot\ {site-name}. Our WEB-INF directory is in C:\Lucee, and we’ve renamed the contexts from the default hash to the {site-name} instead.

So for example I’m seeing this in the C:\lucee\WEB-INF\site1\logs\application.log file:

“ERROR”,“ajp-nio-127.0.0.1-8009-exec-29”,“10/31/2022”,“04:53:38”,“site3”,“FATAL: password authentication failed for user ““cfuser”” Detail: The specific sequence of files included or processed is C:\inetpub\wwwroot\site3\services\dashboardService.cfc:195 C:\inetpub\wwwroot\site3\handlers\Home.cfc:19 C:\inetpub\wwwroot\coldbox\system\web\Controller.cfc:1045 C:\inetpub\wwwroot\coldbox\system\web\Controller.cfc:844 C:\inetpub\wwwroot\coldbox\system\web\Controller.cfc:573 C:\inetpub\wwwroot\coldbox\system\Bootstrap.cfc:253 C:\inetpub\wwwroot\coldbox\system\Bootstrap.cfc:472 C:\inetpub\wwwroot\components\requeststart.cfc:100 C:\inetpub\wwwroot\site3\Application.cfc:68”

Ignore the actual error (cfuser authentication), that is not important. Note the application name in the log entry is site3, even though this log file is located in C:\lucee\WEB-INF\site1\logs. And the error message and the code referenced is obviously from site3.

These applications themselves have not had any major changes lately, however I did migrate them all to new servers recently, with more recent versions of Apache, Tomcat, Lucee, etc. on the new servers. I am also using static defined sites in Tomcat, rather than mod_cfml. If you want to know why, it’s because we occasionally had issues with site4 serving content from site5, for example. It depended on what host header was used when the site was first spun up. I’m using static sites to work around that problem. But now I’m thinking perhaps both of these issues are related to a Lucee bug.

FYI the C:\inetpub\wwwroot\components area is shared by all sites, as is the C:\inetpub\wwwroot\coldbox folder (there are mappings for both of these defined on all the sites).

I should add that the application logs for the other sites are not empty, they do appear to log normally some of the time.

I came across this in the application.log for site3, this might be a clue? Note the application name is “file”, we don’t have any applications with that name so it must be internal to Lucee.
“ERROR”,“ajp-nio-127.0.0.1-8009-exec-7”,“08/11/2022”,“14:01:39”,“file”,“Conflict in same thread: on
[c:\lucee\web-inf\site1\logs\application.log]”

I’m not sure where to start troubleshooting this. Any ideas?

OS: Windows Server 2019
Java Version: 11.0.11
Tomcat Version: 9.0.65
Lucee Version: 5.3.9.166-SNAPSHOT
Apache Version: 2.4

Zackster · November 1, 2022, 5:15pm

I believe, that’s just a symptom of the problem of multiple contexts trying to write to the same file.

What does the list of web contexts at the bottom of the overview page in the server admin look like?

stillnet · November 1, 2022, 6:10pm

Here is the overview page from the bottom of the server admin. I was using the names “site1”, “site3”, etc. in my first post for simplicity, but the actual context names are shown below. These sites are all behind a load balancer, that’s why the hostnames & ports might seem weird.

“qqext” was one that for sure had log entries from other sites in it.

Zackster · November 2, 2022, 9:56am

hmmm, that all looks good.

what does your static context configuration look like?

I believe this is more a problem at the tomcat level, your could try increasing the tomcat log levels

stillnet · November 2, 2022, 1:17pm

My coworker suspects this started happening when we upgraded to 5.3.9.x. We can’t find any occurrences of it happening on the new servers until we upgraded Lucee versions.

Here are my static sites in server.xml.

Zackster · November 2, 2022, 1:45pm

ok, so that all looks good to me.

When you say upgraded to 5.3.9, did you do fresh installs. i.e. tomcat was updated, if so what was the previous version of tomcat?

stillnet · November 2, 2022, 1:57pm

It was a fresh install on the new servers. Yes Tomcat was upgraded, the previous version was whatever was bundled with Lucee 5.3.8.201.

And I was wrong about there being little traffic on the old version. We did have these servers in production on 5.3.8 (unsure of the minor version). The issue only started happening when we switched to 5.3.9. (Tomcat was already upgraded before we switched to 5.3.9).

Zackster · November 2, 2022, 2:06pm

is it possible to try a 5.3.8.201 install upgraded in place to 5.3.9 (i.e. via the admin?) i.e. with the older version of tomcat?

Terry_Whitney · November 2, 2022, 2:07pm

In Server.xml

try updating this:

maxContexts="200"
timeBetweenContexts="2000"

to this:

maxContexts="2000"
timeBetweenContexts="1000"

clear the web-inf folder(s)
restart your lucee instance

stillnet · November 2, 2022, 2:12pm

I believe those parameters apply to mod_cfml, which we are not using.

Terry_Whitney · November 2, 2022, 3:01pm

You are correct that is for the mod_cfml implementation of lucee.

I need more coffee

If apache is set to load balance or proxy pass, if so

I believe you are worker sharing, which the fix would be to look at httpd.conf and set shortest matching url first

https://httpd.apache.org/docs/2.4/mod/mod_proxy.html

stillnet · November 2, 2022, 7:01pm

is it possible to try a 5.3.8.201 install upgraded in place to 5.3.9 (i.e. via the admin?) i.e. with the older version of tomcat?

I’ve given this some thought but haven’t come up with a reasonably easy way to do this, since they are production servers.

Zackster · November 3, 2022, 9:07am

you could set this up locally, just use site1.localhost, site2.localhost which all resolve to 127.0.0.1

JMeter can then access these .localhost sites so you can do some local testing, if you add host entries

here’s a sample jmeter to get you started

lucee-localhost.jmx (14.0 KB)

Phillyun · November 8, 2022, 9:05pm

This happens using Lucee Express 5.3.9.166. It does not happen using 5.3.8.206.

Reproduction steps:

Visit site1 (it will spin for ~10 seconds until it logs the error)

Logs to site1/WEB-INF/lucee/logs/application.log (expected)

Visit site 2 (it will spin for a second until it logs the error)

Logs to site2/WEB-INF/lucee/logs/application.log (expected)

Visit site1

Logs to site2/WEB-INF/lucee/logs/application.log (UNEXPECTED)

Visit site2

Logs to site2/WEB-INF/lucee/logs/application.log (expected)

Subsequent errors on site1 are logged to site2. See log output at the end.

Configuration:
server.xml - added at end of file after default </Host>:

		<Host name="site1.localhost" appBase="webapps">
			<Context path="" docBase="C:\tmp\site1" />
		</Host>
		<Host name="site2.localhost" appBase="webapps">
			<Context path="" docBase="C:\tmp\site2" />
		</Host>

site1/Application.cfc

component output="false" {
	THIS.name = "site1";
	this.tag.log.file="application"; // leads to logging on wrong site
	this.tag.log.application="true";

	public function onError(exception, event) {
		writeLog(type="Information", text="site1 onError fired: Message:#exception.Message#");
		writeOutput("Doh!");
	}
}

site1/index.cfm

<cflog text="site1 hit #now()#">
<cfset foo = bar />
<cfoutput>
site1 hit #now()#
</cfoutput>

site2/Application.cfc

component output="false" {
	THIS.name = "site2";
	this.tag.log.file="application"; // leads to logging on wrong site
	this.tag.log.application="true";

	public function onError(exception, event) {
		writeLog(type="Information", text="site2 onError fired: Message:#exception.Message#");
		writeOutput("Doh!");
	}
}

site2/index.cfm

<cflog text="site2 hit #now()#">
<cfset foo = bar />
<cfoutput>
site2 hit #now()#
</cfoutput>

site1 application.log

"Severity","ThreadID","Date","Time","Application","Message"
"INFO","http-nio-8888-exec-1","11/08/2022","14:49:07","site1","site1 hit {ts '2022-11-08 14:48:47'}"
"INFO","http-nio-8888-exec-1","11/08/2022","14:49:17","site1","site1 onError fired: Message:variable [BAR] doesn't exist"

site2 application.log

"Severity","ThreadID","Date","Time","Application","Message"
"INFO","http-nio-8888-exec-2","11/08/2022","14:49:42","site2","site2 hit {ts '2022-11-08 14:49:20'}"
"INFO","http-nio-8888-exec-2","11/08/2022","14:49:42","site2","site2 onError fired: Message:variable [BAR] doesn't exist"
"INFO","http-nio-8888-exec-3","11/08/2022","14:49:46","site1","site1 hit {ts '2022-11-08 14:49:46'}"
"INFO","http-nio-8888-exec-3","11/08/2022","14:49:46","site1","site1 onError fired: Message:variable [BAR] doesn't exist"
"INFO","http-nio-8888-exec-4","11/08/2022","14:49:49","site2","site2 hit {ts '2022-11-08 14:49:49'}"
"INFO","http-nio-8888-exec-4","11/08/2022","14:49:49","site2","site2 onError fired: Message:variable [BAR] doesn't exist"
"INFO","http-nio-8888-exec-5","11/08/2022","14:50:34","site1","site1 hit {ts '2022-11-08 14:50:34'}"
"INFO","http-nio-8888-exec-5","11/08/2022","14:50:34","site1","site1 onError fired: Message:variable [BAR] doesn't exist"

Zackster · November 8, 2022, 10:01pm

great example, thanks, we’ll investigate [LDEV-4263] - Lucee

cfmitrah · November 10, 2022, 11:50am

@Phillyun cflog file attribute was deprecated. So can you please use this.tag.log.log=“application” instead of this.tag.log.file=“application”

Phillyun · November 10, 2022, 12:31pm

Will give it a try! Thanks

I read the docs twice … I need more coffee and less copy - apparently.
blinks in confused manner

Zackster · November 10, 2022, 12:38pm

good catch

Zackster · November 10, 2022, 12:54pm

Zackster · November 10, 2022, 3:11pm

please try 5.3.10.90, as per [LDEV-4263] - Lucee