Application.log full of unwanted OSGI logs

dev support
#4

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"
#5

What is the exact Lucee version?

the latest 5.3.7 RC apparently doesn’t have this problem anymore https://luceeserver.atlassian.net/browse/LDEV-2516

#6

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

#7

Can confirm that applying 5.3.7 RC resolves the issue.

#9

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"
#10

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

#11

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"
#12

Nope. Just the standard server admin update

#13

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

#14

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?

#15

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)

image
image1086×80 6.17 KB

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.

#16

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 ______________________________________________________________________

#17

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.

#18

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?

#19

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 ?

#20

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
#21

Ok, @justincarter I will check now.

1 Like
#22

I’ve checked this and can able to reproduce with the latest version 5.3.8.20-SNAPSHOT and 5.3.7.34-RC too.

  • But, you can’t see the latest versions of snapshots and RC too if you don’t create a log for application as a separate.
  • This issue will log with application.log in web-inf.
  • But, we couldn’t able to see the application.log in that folder.
  • Because the log not available in web-admin - settings/logging.
  • So, if we create an application.log and level as info means, we could see this below log as level info.

"INFO","ajp-nio-8009-exec-8","07/31/2020","16:59:13","OSGI","add bundle:test\lib\jsoup\jsoup-1.10.2.jar"

#23

the missing application.log is another bug/regression?

bug filed https://luceeserver.atlassian.net/browse/LDEV-2990

#24

Yup, certainly and see No application.log written, but others are because even if you try and fake it the contents are wrong