http://coldfusion.com logo
Join Slack
Powered by
What might cause the dump of the same Java object ...
# lucee
a
What might cause the dump of the same Java object on one Lucee 5.3.9.133 instance to include a section 
bundle-info
at the bottom, and a dump of the same object on a different Lucee 5.3.9.133 instance to not include that section? Both built from the same 
lucee/lucee:5.3.9.133-nginx
Docker image. The Docker config for each is superficially different, but not in any way that ought to impact this. IE: one dump ends with:

https://i2.paste.pics/82d78f78ce4dc51e421fd080ab8c628d.png▾

The other ends with:

https://i2.paste.pics/a03f47f8d4442f253d1156618b620f29.png▾

z
What's the object?
a
It's a third party thing that will be meaningless to you. Why might that matter? (I'm not suggesting it won't matter... just trying to understand why you think it might).
The code in both cases is:
Copy code
<cfdump var="#CreateObject("java", "com.vendor.app.ClassName")#"><cfabort>
It's in the same jar file in the same location in both cases (as per 
bundle-info.location
in the first dump)
d
Is it possible the object was loaded via different methods or that one dump is showing the object after having been created in the request and the other showing the object that's being cached in a scope (or via some other caching mechanism)?
a
Good question, but I mean it's literally that ^^^ exact code (other than the path being sanitised) running on both servers. I copied it from one to the other. Now... one is being called in a single-line .cfm file (containing only that code. No Application.cfc or anything), and the other is via a bunch of other code (including a CFWheels app in the way), but I've made sure that this code is the first and only time 
CreateObject("java", "com.vendor.app.ClassName")
is being called (and it's the only reference to 
com.vendor.app.ClassName
in the codebase), as I did not want any other code "interfering" with it before I call it. I am... 95% nothing else is in play. Both dumps are being done immediately after a Lucee restart, and it's the first request being run on each instance after restart. Any number of other reqs to same code subsequently has no impact on what is dumped.
BTW: it's the version of the code running inside the app that has the 
bundle-info
bit. The one in the straight 
test.cfm
file does not.
OK. A different question. WTF is Lucee doing to my jar file??

https://i2.paste.pics/128fae90f582d5c5701bae58293f1f8a.png▾

I copied the .jar file to 
/opt/lucee/server/lucee-server/context/lib/ezsign-4.1.3.jar
I restarted the container I diffed the two files: same I made the request that has the 
createObject
call in it I diff the two files: now the one at 
/opt/lucee/server/lucee-server/context/lib/ezsign-4.1.3.jar
is different (as indicated above).
d
It feels like there's a class loader involved in the one showing the bundle-info. As for the other question, I wonder if the change is to make the JAR OSGi compliant.
a
That said, it's doing the same thing in both cases, but WTF is it up to?
to make the JAR OSGi compliant.
Oh God. Probably. [despair]
We did have some other jars being loaded via referencing them in 
this.javaSettings
in Application.cfc (or CFWheels's approximation thereof), but I just removed that and no change
Good thinking though
d
Did you restart Lucee? There could be some caching going on. It always seems like I've got to restart Lucee when changing JAR settings if I want to be 100% sure my changes take affect. (This is especially true with ACF)
✅ 1
a
I've factored-out the rest of the application now. I'm using the same one file (exact same file... using a volume from my host machine) in both containers.
yeah I am restarting the container between every test.
It's not a huge issue in and of itself, but it's just the reallyreally code in the second container ain't working, and I can't see why. This dump difference is just... a difference I've noted. I want to understand why it's different, factor it out of being a possible issue, and then move on.
Doing the real testing requires me to deploy everything to prod, which involves our hosting provider (don't ask), and each cycle is slow. So I wanna factor out as much as I can "locally" first.
d
I wish I had an answer for you... It is a weird difference.
a
I bet ya I'm (/we're) doing something daft.
Just can't see it.
d
It feels like the bundle-info is seen when a JAR is OSGi compliant and it's not there when using a non-OSGi compliant JAR.
a
Yeah I did wonder about that sorta thing (didn't think Lucee would actually be changing the jars though!!) but it's doing it in both envs
d
I wonder if maybe in the environment we're you're not seeing it, there's a directory permission preventing the OSGi change you're seeing in the other environment (but maybe you said it was the reverse behavior)
a
I just checked both "changed" files (and they were both changed). binary different, but when I unzipped them, the contents were identical. So am guessing the "difference" is some meta info the re-jar-ing process does or something.
OK... progress... If I copy the "updated" jar file from the "working" container to the "broken" container, restart, retest... I now get the 
bundle-info
in the "broken" container too.
So this sez to me that whatever Lucee is doing to the jar... it's doing it differently in each of these containers.
I blew away the broken container completely and replicated... • at first broken. • replace the "updated" jar file with the initial "unfixed" one... broken. • replace the "broken" container's "fixed" jar with the "fixed" one from the original container... now the broken container "works" as well.
And at this point I am declaring that I have had too many java jars, and not enough beer jars this evening. And I intend to remedy this. @dswitzer I really appreciate your help... got me thinking about stuff. I need to get all this stuff working as a priority, so I will continue tomorrow. If I work anything out, I will report back.
d
@Adam Cameron I'm just happy my input helped you to get to the root cause.
a

https://i2.paste.pics/4c14cf15586bf2f1e176420ad2498cc1.png▾

cheers.
d
Nice to see that "beer jars" was close at hand. 😄
🍻
a
I need to return to this thread about how Lucee messes with third-party jars, and the ramifications thereof. To recap I noticed that how the same Java object dumps out varies for me across two "identical" Lucee containers, and in looking into this I noticed that Lucee is actually changing the third-party jar files. This is... subpar, but it is what it is. In further troubleshooting this, I am noticing some anomalous behaviour that I am struggling to understand and I am 95% certain it's down to Lucee munging with things that it shouldn't. {TBC in thread... gimme 5min to type some more...]
So I stick this jar into 
/opt/lucee/server/lucee-server/context/lib/
via the Dockerfile. I build the container, wait for Lucee to gets its act together and be responsive, and I hit my test code. First time I hit it I get this:
Copy code
No Bundle provided

lucee.runtime.exp.NativeException: No Bundle provided at java.base/java.util.Objects.requireNonNull(Objects.java:246) at org.apache.logging.log4j.core.osgi.BundleContextSelector.locateContext(BundleContextSelector.java:137) at org.apache.logging.log4j.core.osgi.BundleContextSelector.getContext(BundleContextSelector.java:124) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:230) at
@bdw429s if yer reading, this might be familiar to you (https://ortussolutions.atlassian.net/browse/COMMANDBOX-1460). NB: CommandBox is not in play here, I'm just pinging you cos you've experienced this too. Note: I am not directly calling anything to do with Log4J, but the third party code has a wrapper around same, so it will be. If I wait a few sec and run the test code again, this time I get:
Copy code
Could not initialize class com.Moo.Zoo.log.GooLog

lucee.runtime.exp.NativeException: Could not initialize class com.Moo.Zoo.log.GooLog at com.Moo.Zoo.Foo.<init>(Foo.java:103) at com.Moo.Zoo.Foo.<init>(Foo.java:119) at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at
(I've changed a few things in there to redact the vendor & their app) OK so that's already weird. This stays the same for as many re-runs as I like. UNLESS I restart Tomcat (ie via shutdown.sh and startup.sh). Then the code just works. NB: restarting the container doesn't work. It needs to just be a restart of tomcat in the running container. I can reliably repeat this as many times as I want. So what I'd like a clear straight answer on, please, is... WTF? If we can't explain the entire F, then perhaps some lucidity on what Lucee is doing to these poor jar files, and also why I'm getting three different results depending on whether it's the first hit to the jar, subsequent hits to the jar, or subsequent hits to the jar after a Tomcat restart. NB: if I add 
ENV LUCEE_JAVA_OPTS="-DLog4jContextSelector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector"
into my Dockerfile (thanks for the tip there Brad), then the thing works right from the outset.
z
can you post this question to the mailing list? it's a good important topic and it would be good to have this visible (and hopefully the solution) to world for ever, unlike this black hole
a
"This black hole" is externally indexed now, remember
but yeah I can summarise... you mean on that dev.lucee.org thing yeah? That's not just reserved for ppl being rude to each other? There's real content there too? 😉
😆 2
👍 1
🤭 1
z
i thought that's what slack was for?
b
@Adam Cameron I can't explain most of that, but I do know at least one thing-- and I don't know if it's a Lucee behavior or a Java classloader behavior. But I've noticed over the years playing with Java libs that if the INITIALIZTION of a class fails, which can include the static block or the constructor, Lucee/Java/whatever will NOT try and load the class again until you restart the server. That means the "real" error will be a one-time gig and if you miss it, you'll be chasing smoke with the secondary error that happens on all subsequent attempts.
a
\me just opens a vein
i thought that's what slack was for?
We can do it on both, I'm fine with that
z
shall we create some sockpuppets accounts here too?
a
I am just one of Brad's sockpuppets.
✅ 1
I figured you'd worked that out by now
b
On that Log4j osgi bit I never did get to the bottom of it. It was related to Log4j being used in an OSGi environment and attempting to find it's classes via a bundle (instead of straight CL hierarchy). I chased the error all the way to the precipice of the dark chasm of Lucee's OSGI classloading and gave up by just disabling the Log4j feature entirely, lol
a
Yeah if it was on me, I'd get rid of the logging too. We don't even use the part of the app that does any logging. But... outwith our control. I think just adding the 
-D
setting will solve it for us, but I this whole thing smells a bit.
I gotta go watch cricket (if they pub will put it on), but I might summarise on ~FightClub~dev.lucee.org later
👍 2
Cheers both.
z
who's playing cricket?
a
Eng v SAf (ODI) on one screen, Ireland v NZ (T20) on the other
z
been over 4 years since i've sat round and watched some cricket... i miss it
a
Not much cricket going on in Germany I guess. It's nice having a pub half-a-dozen doors up who are completely happy to change one of the half-dozen sports tellies they have onto whatever match is on.

https://i2.paste.pics/5ddecab2349944ba2b869b04796e7965.png▾

p
I definitely wish there were more pubs in my part of the world... Looks like a pretty classic place there 🙂
a
Nice... metadata analysis I guess. I feel doxed! (not). It's a cool pub: It's a Greene King, so a chain, but they give the landlord latitude to select what he stocks and stuff, so there's rotating craft beer for me each other week or so. Used to be a typical crappy "next to the railway station" sort of pub, but they refurbed about a decade ago (!god I've been in South Woodford for ages now), and all the better for it.
Proper doxing:

https://i2.paste.pics/f4cd6e5971c63efb40bd376bf3a92a81.png▾

p
Oh man, I'm totally jealous! I'd love a good place that had some proper British ales mixed in with some craft beer. (Your pic had both the pub and town name on the wall - couldn't resist looking it up.) As a bonus I discovered that image service is blocked at work... lol
🙌 1
a
Oh so it does identify itself in the photo. Not sure it's South Woodford's oldest pub though: I think the George on the high road predates it... it's been there since the 1700s. The railway only went through in the mid 1800s, so would be surprised if there was a pub there before there was a station.
Back on topic (soz), just tested this on CF and it just works, as one would expect and perhaps hope for of Lucee.
Oh and PS: this is all new to 
5.3.9.133
. It works fine on 
5.3.7.47
.
OK transcribed this lot over to https://dev.lucee.org/t/lucee-doing-something-weird-with-third-party-jar-files-change-between-5-3-7-47-and-5-3-9-133/10727. I'm considering this particular thread closed. Cheers all.
2 Views
Open in Slack
PreviousNext
Powered by