Application.log full of unwanted OSGI logs

My application.log seems to have my own statements, as well as ones from OSGI :

"INFO","http-nio-8888-exec-7","06/19/2020","11:16:36","OSGI","add bundle:/wwwroot/clients/p/patientpass/dev/java-libs/aws/joda-time-2.8.1.jar"
"INFO","http-nio-8888-exec-7","06/19/2020","11:16:36","","application started"

Is there any way to filter this log before it is output ? I can’t change every single one of our writelog()'s to a different level, that’s tons of work…

OS: Amzon Linux
Java Version: 11
Lucee Version: Docker - lucee/lucee:5.3-nginx

@thefalken, Change the log level for application.log info to error in the admin-logging.

That removes the OSGI lines, but also my own log ( e.g. CFLOG or writelog() )

For clarity I want to not have the first line in the example above, but keep the 2nd. All in a single file.
I don’t understand what is going wrong, or if Lucee has new defaults, or what.

This is possible to duplicate with the default Docker image @justincarter

Run the image with docker run -p 80:80 -v/tmp/:/var/www lucee/lucee:5.3-nginx

Unpack this .zip into tmp - it contains a very basic Application.cfc and index page that creates a Java object from the included .jar files.
You can unpack anywhere - just adjust the -v above to match

Run the index.cfm via your browser.

To see the log file I ran docker ps then put the name into docker exec -it dazzling_cerf /bin/bash and ran tail -f /opt/lucee/web/logs/application.log
log-test.zip (3.5 MB)
The log file lists multiple unwanted “OSGI add bundle” lines for each request.

"INFO","http-nio-8888-exec-1","06/19/2020","12:54:21","","hi from cf logs"
"INFO","http-nio-8888-exec-1","06/19/2020","12:54:21","OSGI","add bundle:/var/www/java-libs/aws/joda-time-2.8.1.jar"
"INFO","http-nio-8888-exec-1","06/19/2020","12:54:21","OSGI","add bundle:/var/www/java-libs/aws/jackson-databind-2.6.7.3.jar"
"INFO","http-nio-8888-exec-1","06/19/2020","12:54:21","OSGI","add bundle:/var/www/java-libs/aws/jackson-core-2.6.7.jar"
"INFO","http-nio-8888-exec-1","06/19/2020","12:54:21","OSGI","add bundle:/var/www/java-libs/aws/jackson-annotations-2.6.0.jar"

What is the exact Lucee version?

the latest 5.3.7 RC apparently doesn’t have this problem anymore [LDEV-2516] - Lucee

I’m using FROM lucee/lucee:5.3-nginx which is Lucee 5.3.6.61

Can confirm that applying 5.3.7 RC resolves the issue.

Docker image lucee/lucee:5.3.7.34-RC-nginx still has the issue from the same test files

<cflog text="hi from cf logs #serializeJson(server.lucee.version)#">
<cfset f=createObject('java',"com.amazonaws.HttpMethod") />

gives

"INFO","http-nio-8888-exec-2","06/19/2020","14:46:30","","hi from cf logs ""5.3.7.34-RC"""
"INFO","http-nio-8888-exec-2","06/19/2020","14:46:30","OSGI","add bundle:/var/www/java-libs/aws/jackson-annotations-2.6.0.jar"
"INFO","http-nio-8888-exec-2","06/19/2020","14:46:30","OSGI","add bundle:/var/www/java-libs/aws/jackson-core-2.6.7.jar"
"INFO","http-nio-8888-exec-2","06/19/2020","14:46:30","OSGI","add bundle:/var/www/java-libs/aws/jackson-databind-2.6.7.3.jar"

AFAIK, it’s normal you will see that on restart after the upgrade…after 7 days since applying the upgrade, I still have only 1 entry. Keep monitoring. I was getting them every 5 minutes.

3 	 add bundle:C:\lucee\tomcat\lucee-server\bundles\mssqljdbc4-4. 0.2206.100.jar	7 days ago	1   	
4 	 Start bundle: [mssqljdbc4:4.0.2206.100]	7 days ago	1   	
5 	 add bundle:C:\lucee\tomcat\lucee-server\bundles\sun.jai. codec-1.1.2.0003L.jar	7 days ago	1   	
6 	 Start bundle: [metadata.extractor:2.8.1.0002L]	7 days ago	1   	
7 	 add bundle:C:\lucee\tomcat\lucee-server\bundles\lucee.image. extension-1.0.0.35.jar	7 days ago	1  

BTW…if you don’t know there’s a good plugin you can add from the server admin called Log Analyzer

I get an OSGI line for each and every writelog() call, see below.

You are using the RC Docker image ?

"INFO","http-nio-8888-exec-3","06/22/2020","09:06:31","","hi from cf logs"
"INFO","http-nio-8888-exec-3","06/22/2020","09:06:31","OSGI","add bundle:/var/www/java-libs/aws/jackson-annotations-2.6.0.jar"
"INFO","http-nio-8888-exec-3","06/22/2020","09:06:31","OSGI","add bundle:/var/www/java-libs/aws/jackson-core-2.6.7.jar"
"INFO","http-nio-8888-exec-3","06/22/2020","09:06:32","OSGI","add bundle:/var/www/java-libs/aws/jackson-databind-2.6.7.3.jar"
"INFO","http-nio-8888-exec-3","06/22/2020","09:06:32","OSGI","add bundle:/var/www/java-libs/aws/joda-time-2.8.1.jar"
"INFO","http-nio-8888-exec-4","06/22/2020","09:06:32","","hi from cf logs"
"INFO","http-nio-8888-exec-4","06/22/2020","09:06:32","OSGI","add bundle:/var/www/java-libs/aws/jackson-annotations-2.6.0.jar"
"INFO","http-nio-8888-exec-4","06/22/2020","09:06:32","OSGI","add bundle:/var/www/java-libs/aws/jackson-core-2.6.7.jar"
"INFO","http-nio-8888-exec-4","06/22/2020","09:06:32","OSGI","add bundle:/var/www/java-libs/aws/jackson-databind-2.6.7.3.jar"
"INFO","http-nio-8888-exec-4","06/22/2020","09:06:32","OSGI","add bundle:/var/www/java-libs/aws/joda-time-2.8.1.jar"

Nope. Just the standard server admin update

@justincarter is the lucee/lucee:5.3.7.34-RC-nginx updating OK ?

It looks like Lucee is doing that logging for the OSGI bundles that it’s loading. It shouldn’t be specific to using the Docker images, I would guess it’s reproducible in a standard install or in Lucee Express as well?

Docker builds for a specific version number only happen once, so 5.3.7.34-RC was built 22 days ago, and once that image is tagged it will not change (any new builds will have a new version number)

From the comments in the ticket I suspect it’s not fixed in Lucee yet;

https://luceeserver.atlassian.net/browse/LDEV-2516

Pothys - MitrahSoft [June 15, 2020, 9:30 AM]: I’ve checked this with 5.3.7.34-RC and latest snapshot 5.3.8.5_SNAPSHOT also. That latest RC version is not a fix for this issue. Still, it throws an same issue.

I think there’s been a subsequent RC ? Further up the thread ?

______________________________________________________________________ This email has been scanned by the Symantec Email Security.cloud service. For more information please visit http://www.symanteccloud.com ______________________________________________________________________

I suppose what I want @justincarter is a Docker image for 5.3.7.34-RC3 - not the original RC.
I can’t find it listed on https://download.lucee.org/ either so have no idea what to do next to help.
This is killing our logging. It’s impossible to find anything.

I’m not sure what you mean by RC3, RCs are just a snapshot flagged as a RC, 5.3.7.34 is the RC?

I suppose I should have asked:

Is there a later release in 5.3.x series that the .34 RC ?
If not, when might one (assumed with the bug fix, but can’t test till it makes a Docker image) be due ?

The ticket is still “Open” so it doesn’t seem like the issue is fixed yet;
https://luceeserver.atlassian.net/browse/LDEV-2516

The Docker images are essentially builds based on the version numbers that you see on the Lucee Downloads page:
https://download.lucee.org/

I don’t think there’s any such release as 5.3.7.34-RC3, the version number from the downloads page is 5.3.7.34-RC and that’s the version number for the corresponding Docker image. That is also the newest RC, and there are no SNAPSHOT builds after 5.3.7.34 in the 5.3.7.x line. If you wanted to try something newer than that you’d need to try the 5.3.8.20-SNAPSHOT;

image

@cfmitrah Can you confirm this is still a bug in the latest RC and latest SNAPSHOT? If that’s the case, IMO it should be fixed in 5.3.7.x before the release.

1 Like

Ok, @justincarter I will check now.

1 Like