http://coldfusion.com logo
Join Slack
Powered by
Heading into the weekend so I might need to re-ask...
# box-products
d
Heading into the weekend so I might need to re-ask on Monday, but getting an error in our build process with the latest version of CommandBox (5.5.2). Moving from 5.0.1, where this works fine. (picture of error in thread)…
message has been deleted
Actually, 5.5.1 works fine as well. So something with 5.5.2 is going on.
b
@danmurphy your Lucee installation inside CommandBox is corrupted for some reason
The compress extension failed to install
The one line that means anything is this one here
That line of code is
Copy code
zip action="unzip" file="#serverInfo.WARPath#" destination="#serverInfo.serverHomeDirectory#" overwrite="true";
It's a syntx error because Lucee doesn't know about the 
cfzip
tag, which happens when the compress extension doesn't install
d
I can actually reproduce this every time with 5.5.2 within Docker locally too, I’ve realized.
b
You can check the CLI engine's 
deploy
log for clues, but this can also happen if the CLI gets interrutped the first time it runs and Lucee never finished unpacking
5.5.2 ships with a different version of Lucee than 5.0.1 ships with 🙂
👍 1
It's possible something changed in regards to the compress extension version that's bundled
you're the first person to report this though
Does your build server have access to the internet to download things?
d
Do I win a prize?
Yes, it does. You might’ve missed one of my previous comments though, I can reproduce this every time running Docker locally.
b
The compress extension version changed in that committ was was 1 month ago
You might’ve missed one of my previous comments though, I can reproduce this every time running Docker locally.
nope, I saw that, it just doesn't change anything 🙂
There can be a million reasons why something goes wrong, but just because it's consistently wrong in your case doesn't necessarily tell us anything, other than perhaps the fact that' your unlucky
d
That was in reference to this question…
Does your build server have access to the internet to download things?
I was just being clear that it happens on the build server and my local machine every time.
b
The same question applies to your machine, then too, lol
Does it have access to the internet?
That may seem silly to ask, but I have CommandBox users who have zero external internet access on their machines and their servers.
d
Yep, no worries. All is well here with the internet. And I can switch back and forth between 5.5.2 (doesn’t work) and 5.5.1 (works) to see the difference.
b
There are two commons reasons when Lucee fails to have an extension installed • the first start was interrupted • Lucee decided for some crazy reason that its bundled extensions weren't the correct version and it wanted to download it again, but failed to do so
Wait, 5.5.1 or 5.0.1?
you've said both now
Not that it changes the answer, I'm just curious.
d
Yep - either 5.0.1 and 5.5.1 work. 5.5.2 gets that error.
b
Got it
Well, I'd check the deploy log for starters
This is really a Lucee issue
Somehow I always get stuck helping out with Lucee's crap when it happens inside of CommandBox eye roll
I swear 70% of my support time is spent with bugs or issues in 3rd party libraries 😆
d
Ha, sorry!
b
no worries
d
So 5.5.1 runs lucee 5.3.9.133 snapshot, it looks like? And 5.5.2 runs 5.3.9.141?
b
more/less
5.5.1 is actually on the 'stable; build of 5.3.9.131, but they took their sweet, sweet time to get it up on Maven so I had to use the same build from Sonatype, which is listed as a "snapshot" even though it's the same build as the stable one
d
That change you linked to for the compress version bump is 5.3.9.127-snapshot. So would it already be a part of Commandbox 5.5.1?
b
There's not a ton of difference between build 131 and 141
It would seem that it should be a part of 131.
I'm not the expert in that though
Lucee never makes this sort of thing easy to troubleshoot. When extensions fail to installed, Lucee usually glosses over it in layer upon layer of try/catch's in the core designed to keep the server chugging up regardless of how badly mangled it is
If you're lucky, there may be some clues in a log file, but that's not very common
Issues with extensions failing to install are usually sent off into the cold, dark heart of space
d
That is unfortunate.
b
Did you find the deploy log yet?
d
The weird thing is this fails while running a 
Docker build…
so there is no active container to see the logs from. Hmm.
b
Reason #5,624 why I dislike docker: Debugging 😉
d
Totally.
😢
b
Can you reproduce on your local machine?
If not, try just starting up your base image with a 
CMD
of 
bash
or something and then firing off 
box
inside the container to simulate its first start
d
No - I’m running 5.5.2 locally just fine.
b
Then you have a nice running container you can poke around in bash with and test
Are you using the Ortus docker image or another?
d
That’s actually what I’m doing to see this error. It tanks when it hits that 
box info
line in the Dockerfile. (assuming I caught what you were asking)
Copy code
RUN wget -nv <https://downloads.ortussolutions.com/ortussolutions/commandbox/5.5.2/commandbox-debian-5.5.2.deb> \
	&& dpkg -i commandbox-debian-5.5.2.deb \
	&& box info
b
Um, maybe
So you can see the log files now after it errors?
d
Sorry, no. It doesn’t complete building the container because it errors out so there is no container to exec into to see the logs. We have that 
box info
line in our Dockerfile for this reason - so it will tank and kill the build if commandbox doesn’t start up instead of going on thinking all is well. Maybe there is a different way to see files in the container as it is building, but I’m a bit out of my depth here.
b
Then no... you didn't catch what I was asking 😉
I told you how to work around this above
I also asked what your base image is, but you haven't answered yet
I would literally give you commands to run, but I don't know enough info to do that at this point
d
We are using 
lucee/lucee:5.3.9.141-nginx
as our base image.
b
Boo, you should be using the Ortus image 😉
ours have CommandBox already unpacked which would probably have worked around this
d
And this is actually building our base image, not pointing to it from another container/app.
We started with Docker before commandbox had a base image so it was an easier choice back then which one to choose. 😄
b
Regardless, start up the base lucee image with an overridden command that just runs bash. Then run your commands manually one at a time to install and run box
d
I suppose I could build using 5.5.1, start an app with it, download 5.5.2 within it, run it, etc.
b
Or..... take my advice, lol
d
Ok, like you were saying. I see what you’re saying now. Do it manually instead of during the build.
b
I was going to show you what command to run but my freakikng docker machine is out of space again. Reason #5,294 Docker sucks
d
Sorry, I thought I got what you were saying, but it sounds like I missed it? Not trying to be difficult here, just not catching what you mean with the overridden command thing.
b
right, give me a second-- pulling lucee again so I can test the correct command
I hate using Docker on Windows with Docker machine
It's like I'm always fighting with it to make it do what I need 😕
Ok, so just run this
Copy code
docker run -it lucee/lucee bash
That overrides the default command in the lucee docker file so it doesn't start a server, it just starts 
bash
and that's it
now you can manually run your wget and install
And you don't have to worry about a docker build-- you're just playing around in a running container
I get this error
Copy code
root@97703f70c7d5:/usr/local/tomcat# dpkg -i commandbox-debian-5.5.2.deb
Selecting previously unselected package commandbox.
(Reading database ... 12672 files and directories currently installed.)
Preparing to unpack commandbox-debian-5.5.2.deb ...
Unpacking commandbox (5.5.2-1) ...
dpkg: dependency problems prevent configuration of commandbox:
 commandbox depends on java-common; however:
  Package java-common is not installed.
you must have more stuff in your docker file to install java or set the env var for it
d
Yep.
Copy code
RUN apt-get update && apt-get install -y \
	java-common \
    apt-utils
👍 1
b
Ok, it all worked fine on my PC
inside the Lucee container
Copy code
apt-get update && apt-get install -y java-common apt-utils
 wget -nv <https://downloads.ortussolutions.com/ortussolutions/commandbox/5.5.2/commandbox-debian-5.5.2.deb>
 dpkg -i commandbox-debian-5.5.2.deb
 box info
I get the output of the 
info
command in the console
d
What java version?
b
I just ran those commands above ☝️
The 
info
command shows this
Copy code
*  Java Version:       11.0.15 (Oracle Corporation)
*  Java Path:          /usr/local/openjdk-11/bin/java
d
Hmm. Well.
b
I assume that's the version of Java the base Lucee image already has installed
d
It is.
b
OK, you do the same steps
If it works, then go back and run everything in your docker build file to see if any of those steps are getting in the way
once 
box
has come up and run successfully, then Lucee won't unpack again, so if you have a successful test, 
exit
out of the container, and then 
docker run
again to get a fresh slate and start from scratch.
All changes you make inside the container will basically be lost when you 
exit
from the bash shell
And, FWIW, when the lucee container is normally run, the PID 1 is not a 
bash
shell but instead the shell script that actually starts Lucee, so the main process basically IS the Lucee server in that case.
d
Doing it now…
I’m doing it simultaneously in a plain run like you showed and within a container I have running commandbox 5.5.1.
It worked within my own container when I did it manually.
And I’m being called to go grill burgers. So I’ll have to reconvene Monday. 😢
b
ok, so go back and start at the top of your docker file and redo your test, manually running every single thing that happens in your actual docker build to see if anything influences it
Burgers sound great.
It's 7pm here and I'm surprised my wife hasn't drug me away from my desk 🙂
😂 1
d
So running manually works just fine. During the automatic build, it fails every time (on the build server or locally). The only things in-between the FROM line of the Dockerfile and the lines where commandbox is installed are two lines…
Copy code
ENV LUCEE_JAVA_OPTS="-Xms256m -Xmx2048m"
ENV LUCEE_EXTENSIONS "CED6227E-0F49-6367-A68D21AACA6B07E8;name=admin;version=1.0.0.3, D4EDFDBD-A9A3-E9AF-597322D767E0C949;name=oracle;version=21.3.0.0000, 66E312DD-D083-27C0-64189D16753FD6F0;name=pdf;version=1.1.0.7"
It seems like that shouldn’t mess with what commandbox is doing though. 🤔
I’ll remove those lines to test stuff out between meetings later today. I’ll report back.
@bdw429s - the 
ENV_LUCEE_EXTENSIONS
line is the culprit. Removing that line makes the error go away and CommandBox installs properly every time. That’s weird, right?
b
Not weird at all-- that line will 100% for sure totally affect how CommandBox starts, lol
In fact, that's vital information that probably should have been reported in your very first message 🙂
The Lucee server that powers CommandBox itself will also pick up that env var (I assume your server was the intended target) and the CLI will also attempt to install those extensions.
After all, any Lucee process that runs inside of that environment, whether it's the CLI or the web server, will all "see" that env var and use it.
Now what's interesting is that the extensions you're installing appear to just be the admin, Oracle JDBC, and PDF ones, and noting related to the Compress extension.
But no matter-- those custom extension installs are somehow changing what Lucee does internally and seem to be affecting the proper installation of the Compress extension.
@danmurphy
d
Well, that answers it then. We aren't installing the compress extension so it isn't available to the Lucee insurance commandox is using. I had no idea commandbox would pick those up automatically. Why does this break only starting in 5.5.2?
b
hold on-- when you say you're not "insatalling it", what do you mean
Assuming you're not using Lucee Lite, all the core extensinos are avaialble
So unless you're explicitly UNINSTALLING it, it's going to be there
The 
LUCEE_EXTENSIONS
env var only ADDS extensions, it doesn't remove them
I had no idea commandbox would pick those up automatically.
To be clear, LUCEE picks it up. CommandBox really has nothing to do with any of this. CommandBox just embeds a Lucee instance.
Why does this break only starting in 5.5.2?
This is a great question for the Lucee developers to answer for you. I have no freaking clue, lol
d
Huh, that hasn't been our experience. It seems like that is the complete list of extensions installed, when included.
b
But again, unless you're using an env var to explicitly uninstall extensions, you're not going to 'get rid' of an extension with that env var
Nope, I can 100% promise you that's not how that works
I've used that env var for hundreds of client projects to just add one additional extension to the list.
It's never been a comprehensive list
Now, that said-- the official Lucee docker images may start with Lucee light
Which would mean, THAT specific instance of Lucee that is powering the web server of your docker container may only have what you ask for
But CommandBox's embedded version of Lucee is the "normal" Lucee and does have the compress extension in it
And your env var won't remove anything, but it will trigger Lucee to install those extensions
That's just now Lucee works-- when you start up Lucee in any process whose environment contains a LUCEE_EXTENSIONS variable, it will pick it up and use it
If you wanted to try a quick workaround, you could just move the declaration of that env var into Tomcat's setenv.sh file so it's only visible do your web server and the CLI won't see it.
The shell scripts that actually start your server are a subprocess and have their own env vars.
d
But with that included env var, commandbox's instance of Lucee didn't have the compress extension installed, right? Wouldn't that prove the comprehensive list theory?
b
No
There's like a million possible code paths Lucee could have taken internally.
Perhaps something errored and it stopped installation extensions and never finished
Who knows
I've read the code inside Lucee's Java source. The env var ONLY ADDS extensions. It does not remove
You've just assumed that because I'm fairly sure the Lucee docker images use Lucee light, so they always started with a blank slate
If I put beer in the fridge, but the fridge was empty to start with, there will only be beer and nothing else in the fridge. That doesn't mean I removed anything, it just means there was nothing else there to start.
d
But why does Commandbox's instance get impacted? I'm not doing anything but listing that env var and it fails. If I don't include it, the compress extension must be there because it doesn't fail.
b
I'd love to know too, but I'm confused why you keep asking me, lol
I didn't write Lucee and I don't maintain it!
Ask Micha, or Zac- it's their product
I'm just trying to help you out here because CommandBox uses Lucee
ok, I was able to reproduce-- I had to set the env var and then export it and then run box
Copy code
root@7717c062ec89:/usr/local/tomcat# history
    1  LUCEE_EXTENSIONS="CED6227E-0F49-6367-A68D21AACA6B07E8;name=admin;version=1.0.0.3,D4EDFDBD-A9A3-E9AF-597322D767E0C949;name=oracle;version=21.3.0.0000,66E312DD-D083-27C0-64189D16753FD6F0;name=pdf;version=1.1.0.7"
    2  export LUCEE_EXTENSIONS
    3  wget -nv <https://downloads.ortussolutions.com/ortussolutions/commandbox/5.5.2/commandbox-debian-5.5.2.deb>
    4  apt-get update && apt-get install -y java-common apt-utils
    5  dpkg -i commandbox-debian-5.5.2.deb
    6  box
At least it's repeatable
now to see what's in the logs
Hmmmm, right off I see this in the deploy log
Copy code
"INFO","main","06/06/2022","15:58:53","controller","unsuccessfully installed extensions :7E673D...
And then I see a bunch of lines of it appearing to REMOVE stuff-- possibly due to the failure (which doesn't seem to be logged anywhere)
I think it's possible some sort of failure in adding your custom extensions is causing LUcee to try and roll it all back and rip stuff out. Just a guess. The default log level of the deploy log doesn't have everything
Oh look-- the logic that outputs that exact error message was touched last month! https://github.com/lucee/Lucee/blame/6.0/core/src/main/java/lucee/runtime/engine/CFMLEngineImpl.java#L377
Let's see if those changes were part of the 5.3.9.141 release
Hmm, not sure, but there were some other logging changes in that same file back in May
OK, back to looking at the logs-- Lucee totally rips out the cfzip tag definitions after it thinks the install fails
Copy code
"INFO","Thread-10","06/06/2022","15:59:04","extension","Remove TLD file ziptag.tldx"
That's one of the last lines in the deploy log
What I still can't find is what the heck errored. There are no exceptions in the deploy log
This docker image has some really screwy permissions by the way-- I can't even list out the files correctly in the CommandBox home. Do you get this?
Copy code
root@7717c062ec89:~/.CommandBox/engine/cfml/cli/lucee-server/context/logs# ls -la
ls: cannot access 'mapping.log': Operation not permitted
ls: cannot access 'scope.log': Operation not permitted
ls: cannot access 'requesttimeout.log': Operation not permitted
ls: cannot access 'mail.log': Operation not permitted
ls: cannot access 'trace.log': Operation not permitted
ls: cannot access 'deploy.log': Operation not permitted
ls: cannot access 'out': Operation not permitted
ls: cannot access 'memory.log': Operation not permitted
ls: cannot access 'gateway.log': Operation not permitted
ls: cannot access 'out.log': Operation not permitted
ls: cannot access 'orm.log': Operation not permitted
ls: cannot access '.': Operation not permitted
ls: cannot access 'err': Operation not permitted
ls: cannot access 'thread.log': Operation not permitted
ls: cannot access '..': Operation not permitted
ls: cannot access 'remoteclient.log': Operation not permitted
ls: cannot access 'felix.log': Operation not permitted
ls: cannot access 'search.log': Operation not permitted
ls: cannot access 'datasource.log': Operation not permitted
ls: cannot access 'scheduler.log': Operation not permitted
ls: cannot access 'application.log': Operation not permitted
ls: cannot access 'rest.log': Operation not permitted
ls: cannot access 'exception.log': Operation not permitted
total 0
d????????? ? ? ? ?            ? .
d????????? ? ? ? ?            ? ..
-????????? ? ? ? ?            ? application.log
-????????? ? ? ? ?            ? datasource.log
-????????? ? ? ? ?            ? deploy.log
-????????? ? ? ? ?            ? err
-????????? ? ? ? ?            ? exception.log
-????????? ? ? ? ?            ? felix.log
-????????? ? ? ? ?            ? gateway.log
-????????? ? ? ? ?            ? mail.log
-????????? ? ? ? ?            ? mapping.log
-????????? ? ? ? ?            ? memory.log
-????????? ? ? ? ?            ? orm.log
-????????? ? ? ? ?            ? out
-????????? ? ? ? ?            ? out.log
-????????? ? ? ? ?            ? remoteclient.log
-????????? ? ? ? ?            ? requesttimeout.log
-????????? ? ? ? ?            ? rest.log
-????????? ? ? ? ?            ? scheduler.log
-????????? ? ? ? ?            ? scope.log
-????????? ? ? ? ?            ? search.log
-????????? ? ? ? ?            ? thread.log
-????????? ? ? ? ?            ? trace.log
I'm running as 
root
so that's a really odd error. makes me wonder if it's related to Lucee not working correctly
Hmm, this is annoying- after deleting the CommandBox home, restoring a default Lucee config XML file with the 
deploy
log set to a level of 
trace
and the restarting 
box
, I still only get 
info
messages in the log file.
I'm not sure how to tell what the actual error is that Lucee is running into!!
@zackster Any ideas on why setting my Lucee deploy log level to 
trace
or 
debug
before the server starts the first time isn't getting picked up?
I created the folders and lucee-server.xml file and put this line in there
Copy code
<logger appender="resource" appender-arguments="path:{lucee-config}/logs/deploy.log" layout="classic" level="debug" name="deploy"/>
and then start the server the first time, but I still only get 
INFO
message in the deploy log. What gives?
Here's the full contents of my deploy log when the issue happens. You can see, it only has 
info
messages regardless of what I set the log level to ahead of time
The important bits are this... This line is good, it's just Lucee doing the normal install of the embedded extensions
Copy code
detected Extensions to install (new;new-fresh) ...
This is also fine, it's just Lucee detecting the env var
Copy code
extensions to install defined in env variable or system property: ...
here is the compress extension actually getting installed-- good.
Copy code
installing the extension 8D7FB0DF-08BB-1589-FE3975678F07DB17;name=Compress;label=Compress;version=1.0.0.7;since=5.3.2.31-SNAPSHOT
installing the extension 8D7FB0DF-08BB-1589-FE3975678F07DB17;name=Compress;label=Compress;version=1.0.0.7;since=5.3.2.31-SNAPSHOT from local provider
Deploy tld/tldx [ziptag.tldx]
And now, for no apparent reason, Lucee reports everything was a failure
Copy code
unsuccessfully installed extensions : ...
And then it uninstalls the compress extension (among others)
Copy code
Remove TLD file ziptag.tldx
Deploy tld/tldx [ziptag.tldx]
Without the logging working, I can't debug any further without creating a custom-compiled version of Lucee to trace what the heck it's doing.
I'd say it's time for Micha to come explain what's going on here 🙂
@danmurphy
d
Sorry, was off to meetings. This is great, Brad, thanks for digging in. Glad you can reproduce it. Curious if @micha or @zackster can shed some light on this one.
b
@danmurphy In other news, did you try my suggested workaround and did it work?
I have other ideas too-- I'm just waiting until I hear back 👍 or 👎 from the first one.
d
It was actually simpler than that even. I put the ENV line after the commandbox install and it worked just fine.
b
That was going to be my next idea 😉
It's still worth noting, Lucee will still see and process that env var inside CommandBox every time it runs.
👍 1
Which means, it is probably still installing those extensions into the CLI when you run your CFConfig command, but so long as it doesn't puke there, it's an improvement!
d
Exactly
b
If we don't get a reply here, a ticket or at least a thread on the Lucee dev forum about this would be good.
Either way, I need to know why • trace/debug logging no longer works in the deploy log • That env var shows a mystery failure that prevents all the extensions from installing
@danmurphy Did you get a JIRA ticket or at least a Discourse post created for this behavior?
d
Just getting back into the swing of things after a couple of weeks off - I’ll get a Lucee ticket created. Trying to refresh my memory on the reproducible steps too. 😜
Open in Slack
PreviousNext
Powered by