http://coldfusion.com logo
Join Slack
Powered by
OK, we've been having an issue where Lucee's loggi...
# lucee
a
OK, we've been having an issue where Lucee's logging stops "periodically". We're on Lucee 5.3.9.173. It seems to be a variant of https://luceeserver.atlassian.net/browse/LDEV-4035, wherein the logging level is being reset to ERROR (the logs are actually configured as INFO). It seems to occur when we load a Java library that has its own Log4J usage. It's as if creating the pertinent object in this lib is somehow causing Lucee to reset its logging, but not with the saved config (if that makes sense). I'm gonna contact the vendor and see if they're doing anything "non-standard" around Log4J, to maybe get a better understanding of what's going on. But I am no Java dev so things will go over my head fairly quickly. I strongly suspect they're not doing anything untoward, that said. I need to work around this situation asap. Is there any way to force Lucee to reload its log settings from the saved config an runtime? I'm kinda loath to change all our logging to ERROR just to work around this.
z
is the java library using OSGI or a classic jar, theory being if it was loaded by osgi, then it's in it's own classloader and lucee wouldn't be setting the configuration from that library?
a
It's a classic jar as far as I know.
I have some more on this. The third party code we're using takes some logging config, which includes a log-level. It's designed to run on its own JVM, so when this setting is passed, it will do [whatever] to reset the log level for its logging. It sounds like it will be doing this to the JVM's default Log4J "system" (I'm sound vague as I have NFI how Log4J stuff can be configured for a JVM, and to be frank I don't want to know either. So. We run the code to init this third party object. We are passing it a log level. It resets the shared(?) Log4J log level, or causes config to reload or something like that? At which point... Lucee resets the log level on all its configured logs to be ERROR. Note: the code configuring the third party object is NOT setting any log level to ERROR; it's setting it to DEBUG. so it's not that this setting for this object's logging is overriding Lucee's logs. However it's triggering Lucee to do something wrong. I realise we are running code that triggers [whatevs], but it really does seem to me like an unhandled symptom of https://luceeserver.atlassian.net/browse/LDEV-4035, so not sure it's fixed. We're on 5.3.9.173. I'm 80% "sure" this was not an issue on 5.3.9.166. The code in question has been around for years, and we've only started noticing the logging stop in our recent attempts to upgrade from 5.3.9.166. However this could also be confirmation bias: we're looking at the logs more these days too.
I think I will be able to repro this in dev now, so I can poss confirm behavioural changes between Lucee versions. I'll report back either way
z
this is the same problem you were hitting with 5.4.x ?
a
Yes
Like I said, I'm not 100% that it's actually tied to a Lucee version / gets worse with a Lucee version. I should know more this afternoon or tomorrow, hopefully.
z
I did discuss your problem a bit with @micha last week, he confirmed, that using OSGI may isolate this libraries config from the main lucee config, but even when using OSGI, he mentioned it depends on what the developers are doing with classloaders
a
I don't quite get how changing the log level on their log has any impact on [my other log] though. It seems like it's triggering a "global" reload the log settings, which is less than ideal but so be it. And Lucee isn't reloading the settings properly
Well: Lucee is def not reloading the settings properly. If this code was simply changing the log level across the board, it'd be changing everything to DEBUG, not ERROR. This is too close to that ticket where there was that other glitch which was causing Lucee to reset to ERROR.
z
if you can share some code offline, @micha can debug it and answer the question, at the moment we are throwing darts after a few too may pints 😉
a
Ah the good news is I can reproduce in dev now. The bad news is I can repro it back to 5.3.9.133, which is means my theory that it was a regression at some point was wrong. To share the code yer gonna need a Google KMS account, otherwise it won't run... I can see if I can send you the jar file, and how we're calling it from Lucee? But to confirm, here's pseudo code:
Copy code
new Administrator("web", server.system.environment.LUCEE_PASSWORD).updateLogSettings(
    name = "whatevs",
    level = "INFO",
    appenderClass = "lucee.commons.io.log.log4j2.appender.ResourceAppender",
    layoutClass = "lucee.commons.io.log.log4j2.layout.ClassicLayout",
    appenderArgs = {maxfiles = 20, maxfilesize = 1073741824}
)

// ...

writeLog(log="whatevs", type="info", text="this logs fine")
writeLog(log="whatevs", type="error", text="this logs fine")
callThirdPartyCodeHere()
writeLog(log="whatevs", type="info", text="no sign of this") // <----------------- :-(
writeLog(log="whatevs", type="error", text="this logs fine")
Now I don't doubt that 
callThirdPartyCodeHere
is triggering [whatever], but it's not what is resetting the 
whatevs
log to be log level ERROR. That's Lucee doing that. NB: I can see the log's config in 
/opt/lucee/web/lucee-web.xml.cfm
, and it says 
level="info"
, and the rest of the settings are the same as in the 
updateLogSettings
call.
2 Views
Open in Slack
PreviousNext
Powered by