Hi at the end of last week we had an incident where our Luce cfml #lucee

Hi, at the end of last week we had an incident whe...

Peter Bennett

07/06/2023, 1:56 PM

Hi, at the end of last week we had an incident where our Lucee instance was reinitialising itself several times. We are running cfwheels. In the logs, it looks like lucee.runtime.config.XMLConfigWebFactory java.lang.NullPointerException was related to a call to updateLogSettings in /Application.cfc:98, which is the code below: Has anyone else encountered this issue before? admin.updateLogSettings( name = arguments.name, level = arguments.level, appenderClass = "lucee.commons.io.log.log4j2.appender.ResourceAppender", layoutClass = "lucee.commons.io.log.log4j2.layout.ClassicLayout", appenderArgs = { maxfiles = 20, maxfilesize = 1073741824 } ) 2023-06-30 143833.557 lucee.runtime.config.XMLConfigWebFactory /resource/context/lucee-doc.lar 2023-06-30 143833.557 lucee.runtime.config.XMLConfigWebFactory /opt/lucee/web/context/lucee-doc.lar 2023-06-30 143833.557 lucee.runtime.config.XMLConfigWebFactory java.lang.NullPointerException at org.apache.felix.framework.BundleRevisionImpl.getResourceLocal(BundleRevisionImpl.java:506) at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1537) at org.apache.felix.framework.BundleWiringImpl.getResourceByDelegation(BundleWiringImpl.java:1386) at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.getResource(BundleWiringImpl.java:2434) at java.base/java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:1737) at java.base/java.lang.Class.getResourceAsStream(Class.java:2650) at lucee.runtime.config.XMLConfigWebFactory.createFileFromResourceCheckSizeDiff(XMLConfigWebFactory.java:1137) at lucee.runtime.config.XMLConfigWebFactory.createFileFromResourceCheckSizeDiffEL(XMLConfigWebFactory.java:1118) at lucee.runtime.config.XMLConfigWebFactory.createContextFiles(XMLConfigWebFactory.java:1229) at lucee.runtime.config.XMLConfigWebFactory.reloadInstance(XMLConfigWebFactory.java:335) at lucee.runtime.config.XMLConfigAdmin._reload(XMLConfigAdmin.java:327) at lucee.runtime.config.XMLConfigAdmin.storeAndReload(XMLConfigAdmin.java:305) at lucee.runtime.tag.Admin.store(Admin.java:5240) at lucee.runtime.tag.Admin.doUpdateLogSettings(Admin.java:4712) at lucee.runtime.tag.Admin._doStartTag(Admin.java:721) at lucee.runtime.tag.Admin.doStartTag(Admin.java:355) at org.lucee.cfml.administrator_cfc$cf.udfCallc(/org/lucee/cfml/Administrator.cfc:1993) at org.lucee.cfml.administrator_cfc$cf.udfCall(/org/lucee/cfml/Administrator.cfc) at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112) at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350) at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213) at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698) at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585) at lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1951) at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866) at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1792) at application_cfc$cf.udfCall(/Application.cfc:98) at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112) at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350) at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213) at lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804) at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866) at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1792) at application_cfc$cf.udfCall(/Application.cfc:77) at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112) at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350) at lucee.runtime.type.UDFImpl.call(UDFImpl.java:218) at lucee.runtime.type.EnvUDF.call(EnvUDF.java:109) at lucee.runtime.functions.closure.Each._call(Each.java:214) at lucee.runtime.functions.closure.Each.invoke(Each.java:170) at lucee.runtime.functions.closure.Each._call(Each.java:89) at lucee.runtime.functions.closure.Each.call(Each.java:66) at lucee.runtime.functions.arrays.ArrayEach._call(ArrayEach.java:51) at lucee.runtime.functions.arrays.ArrayEach.call(ArrayEach.java:38) at lucee.runtime.functions.arrays.ArrayEach.invoke(ArrayEach.java:67) at lucee.runtime.interpreter.ref.func.BIFCall.getValue(BIFCall.java:134) at lucee.runtime.type.util.MemberUtil.call(MemberUtil.java:126) at lucee.runtime.type.util.ArraySupport.call(ArraySupport.java:322) at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787) at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1773) at application_cfc$cf.udfCall(/Application.cfc:77) at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112) at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350) at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223) at lucee.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:786) at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787) at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1773) at events.onapplicationstart_cfm$cf.call(/events/onapplicationstart.cfm:10) at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:1054) at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:946) at lucee.runtime.PageContextImpl.doInclude(PageContextImpl.java:927) at wheels.global.cfml_cfm$cf.udfCall1(/wheels/global/cfml.cfm:111) at wheels.global.cfml_cfm$cf.udfCall(/wheels/global/cfml.cfm) at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112) at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350) at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213) at lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804) at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866) at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1792) at wheels.events.onapplicationstart_cfm$cf.udfCall(/wheels/events/onapplicationstart.cfm:398) at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112) at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350) at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223) at lucee.runtime.ComponentImpl._call(ComponentImpl.java:697) at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585) at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1932) at lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java:444) at lucee.runtime.listener.ModernAppListener.onApplicationStart(ModernAppListener.java:306) at lucee.runtime.PageContextImpl.initApplicationContext(PageContextImpl.java:3165) at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:122) at lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:44) at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2490) at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2476) at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2447) at lucee.runtime.engine.Request.exe(Request.java:45) at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1198) at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1144) at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97) at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)

zackster

07/06/2023, 1:57 PM

always mention the relevant software versions please :)

bdw429s

07/06/2023, 1:58 PM

Are you updating the log settings on every request? If that reinitializes the underlying Log4j engine, I wouldn't expect that to be thread safe.

👍 1

bdw429s

07/06/2023, 1:59 PM

What method in your Application.cfc is line 98?

bdw429s

07/06/2023, 1:59 PM

@Peter Bennett

Peter Bennett

07/06/2023, 2:24 PM

Hi, sorry, it's $initialiseLog()

bdw429s

07/06/2023, 2:26 PM

Sorry, I was trying to find out what listener method in application.cfc it was inside of

bdw429s

07/06/2023, 2:26 PM

onRequestStart, onApplicationStart, ect

bdw429s

07/06/2023, 2:26 PM

Also, can you answer my other question I asked?

bdw429s

07/06/2023, 2:26 PM

Are you updating the log settings on every request? If that reinitializes the underlying Log4j engine, I wouldn't expect that to be thread safe.

zackster

07/06/2023, 2:26 PM

and lucee version?

Peter Bennett

07/06/2023, 2:31 PM

Lucee 5.3.9.166 onApplicationStart

zackster

07/06/2023, 2:33 PM

can u repo in dev?

Peter Bennett

07/06/2023, 2:47 PM

Old CFWheels 1.4.5

zackster

07/06/2023, 2:51 PM

anyway, like brad said, configure your server outside the app

Peter Bennett

07/06/2023, 2:51 PM

thanks

Adam Cameron

07/07/2023, 7:03 AM

Whilst the observations about the quality of the code in question are valid (Pete is my colleague; it's our - legacy - code, and this approach is terrible, I know), I don't think they do much to address the actual question. The code is being run in

onApplicationStart

, which is single-threaded (or is supposed to be...). And that aside, how would the code get into the specific situation that caused the issue even if it was being run by concurrent threads? But like, it wasn't, so that question is "as a matter of interest", not "part of the problem" here.

zackster

07/07/2023, 7:07 AM

fair point, but also back to first principles, does it happen with the latest version?

zackster

07/07/2023, 7:07 AM

with the latest version, what does the out.log / err.log look like?

zackster

07/07/2023, 7:08 AM

secondly, which log is it updating?

Adam Cameron

07/07/2023, 7:11 AM

I had a look-see at the time, and that stack trace was the only relevant thing logged anywhere. Pete's not in today, so won't be able to follow this lot up further as I don't wanna be stepping on his toes when it was me who asked him to look into it in the first place. We are not in the position to upgrade out production environment to a subsequent version of Lucee ATM. Still testing 5.4 in dev (although thinking about putting it on Sandbox next week for a bit). No way we will be moving to 6.x in the near future, until it's been put through its paces by more of the community after its proper release.

Adam Cameron

07/07/2023, 7:12 AM

We are making that same call to

updateLogSettings

a bunch of times in rapid succession. I wonder if it's got a concurrency issue in that it's returning before it's finished writing-back the updated XML config file "because performance" or something?

Adam Cameron

07/07/2023, 7:13 AM

eg like:

Copy code

ourLogConfigWhichHasTenElements.each(() => {
    // stuff
    admin.updateLogSettings(etc)
})

zackster

07/07/2023, 7:18 AM

yeah, each time you update the config, it's doing a full config reload. you can see that in the

out.log

zackster

07/07/2023, 7:19 AM

but there has also been a lot of work around logging since 5.3.9.160

zackster

07/07/2023, 7:22 AM

so while it's in onApplication start, other things might be writing logs aside from just your application

Adam Cameron

07/07/2023, 7:29 AM

Right so it sounds to me like that code should possibly be controlling itself better so other stuff ain't reading when something else is writing. User-land code should not be able to trigger that sort of situation. But as you say, perhaps not something to worry too much about as we're on 5.3.9.166, and that's a bit long in the tooth. We really ought to move that code to an

onServerStart

handler anyhow. The logs write to a volume, so we can't push it all the way back into the Docker image. I think. It's just one of those things that falls into the category of "it's a bit shit, but... not causing us as much grief as other stuff is, so we'll just grimace when we look at it, but move on". This is the first time it's given us probs. If it persists, I'll look at it some more. Cheers mate.

zackster

07/07/2023, 7:32 AM

still i'd be keen to know if it blows up with 5.4.1.5 🙂

zackster

07/07/2023, 7:32 AM

it's 2023, you can just drop a .CFconfig.json in the webroot 🙂

Adam Cameron

07/07/2023, 7:35 AM

We're a month away from being in prod with 5,4 (and it's only 5.4.0.80 that we're smoke testing on anyhow). Doesn't .cfconfig.json require... configbox or cfconfig or whatever it is? "it's 2023... we shouldn't need third party add-ons to manage the config of your app server", would be my reaction to that.

Adam Cameron

07/07/2023, 7:35 AM

(comment equally aimed @ CF, btw)

zackster

07/07/2023, 7:35 AM

nah, built in since 5.3.9 ish

Adam Cameron

07/07/2023, 7:35 AM

Oh!

Adam Cameron

07/07/2023, 7:37 AM

Aha: https://luceeserver.atlassian.net/browse/LDEV-4168

Adam Cameron

07/07/2023, 7:37 AM

5.3.10.65

Adam Cameron

07/07/2023, 7:37 AM

INteresting

Adam Cameron

07/07/2023, 7:38 AM

I might get someone to investigate that

Adam Cameron

07/07/2023, 7:38 AM

Cheers for the tip. And welcome to the 2020s, Lucee

Adam Cameron

07/07/2023, 7:38 AM

😄

zackster

07/07/2023, 7:38 AM

6.0 now has request blocking during extension installs

Adam Cameron

07/07/2023, 7:38 AM

Good. Kinda necessary, I'd've thought

zackster

07/07/2023, 7:39 AM

otherwise in place upgrades under load was rather a shit show!

Adam Cameron

07/07/2023, 7:39 AM

aah.. yeah can imagine.

zackster

07/07/2023, 7:39 AM

found a few bugs tho hehehe

Adam Cameron

07/07/2023, 7:39 AM

but you'd be a loon to do an upgrade on an active server anyhow. So perhaps deserve what you get.

Adam Cameron

07/07/2023, 7:42 AM

Oh heads-up again... https://hub.docker.com/r/lucee/lucee still says 5.3 is the latest stable

zackster

07/07/2023, 7:45 AM

waves to @justincarter

justincarter

07/07/2023, 7:48 AM

I finally updated the readme in GitHub the other day, should be able to do some copy pasta into Docker Hub 😁

⭐ 2

Open in Slack

Previous Next