Showing posts with label Lucee. Show all posts
Showing posts with label Lucee. Show all posts

Thursday, 16 February 2023

Lucee bug surfaced by CFWheels's "architecture"

G'day:

Well here's a fine use of my frickin time.

Lucee's released a new "stable" version and we're being encouraged to use it. Today I upgraded my dev environment to Lucee 5.3.10.120 (from 5.3.9.166 which seems quite stable and gave us no issues), ran our tests to see if anything obvious went wrong, and a whole lot of them went splat. All of them were variations of this (this is from my repro case, not our codebase):

Lucee 5.3.10.120 Error (expression)
MessageCannot update key [MAORI_NUMBERS] in static scope from component [cfml.vendor.lucee.staticFinal.C], that member is set to final
StacktraceThe Error Occurred in
/var/www/cfml/vendor/lucee/staticFinal/C.cfc: line 5
3: static {
4: final static.MAORI_NUMBERS = ["tahi", "rua", "toru", "wha"]
5: }
6: }

called from /var/www/cfml/vendor/lucee/staticFinal/C.cfc: line 1
called from /var/www/cfml/vendor/lucee/staticFinal/test.cfm: line 2

The code in question is this:

component extends=Base {

    static {
        final static.MAORI_NUMBERS = ["tahi", "rua", "toru", "wha"]
    }
}

I am not trying to "update key [MAORI_NUMBERS] [etc]", I am simply trying to create the object.

Roll back to 5.3.9.166: code works.

My initial attempt to reproduce the error was just this:

component {

    static {
        final static.MAORI_NUMBERS = ["tahi", "rua", "toru", "wha"]
    }
}

But that worked fine, no errors.

Notice how I am not extending anything there? This is significant.

What's in Base.cfc? I'm kind of embarrassed to show you this.

component {

    include "include.cfm";
}

"WTF?" you might legitimately ask. Well: quite. The thing is I found this issue in a CFWheels application, and it's down to CFWheels's "architecture" that this bug in Lucee surfaces.

Look at this… stuff:

component output="false" displayName="Model" {

    include "model/functions.cfm";
    include "global/functions.cfm";
    include "plugins/standalone/injection.cfm";

}

That's how CFWheels implements its base model class. They are pretending CFML has mixins (it doesn't) by using includes. All their classes seem to be defined as a series of include files. I just… just… I just… … aaaaaaaah!!! Just do me a favour and don't use CFWheels. Trust me.

Anyway, so this is why I'm writing shit code to reproduce this Lucee bug.

In include.cfm I have this:

public function build() {
    return this
}

(This is also how CFWheels initialises its model class objects: using a sort of factory method. So I'm replicating a pared-down version of that).

And CFWheels creates its objects like this (in test.cfm):

<cfinvoke component="C" method="build" returnVariable="o">

Yeah. <cfinvoke>. Ain't seen one of those in about a decade (and it was old code then…).

And if I run that code, I get the error concerned.

I've tried to pare it back further, but it seems I need the sub class, base class, include combo. Lucee is - it seems - doing something dodgy when it instantiates an object like this. No surprise they didn't catch it during their own tests, because this is a very - um - "edge case" approach to designing code.

Another weird thing is that if I restart my Docker container: the problem goes away. However if I then do something like change the name of include.cfm to includex.cfm or something, the problem comes back. Adding code to either CFC does not bring the issue back (if you see what I mean). It's def down to something about how a base class that has an include in it is first "created" (I hesitate to say "compiled" here, cos then I don't think the issue would magically go away between container restarts: the compiled code seems fine. Just the in-memory code after the compilation the first time round is crocked. Anyhow, I won't try to guess what's wrong, I'll leave that to the Lucee bods. They can have my repro case to help them (here on GitHub: /vendor/lucee/staticFinal).

I encountered a ColdFusion bug during assessing this: time to write that one up. (update: this one has already been reported, as it turns out: CF-4213214).

Righto.

--
Adam

Wednesday, 15 February 2023

CFML: runAsync doesn't seem very asynchronous on Lucee (5.3.10.120)

G'day:

I was wanting to compare how other languages dealt with the promise-style async processing, as I was not completely convinced by what I was seeing when investigating spatie/async in the previous article: "PHP: looking at spatie/async". It seems solid, just doesn't behave how I'd expect in some situations. More on that in another article. I checked what JS does, and it was fine, and then I recalled in the back of my mind that CFML added something new to do with async processing a while ago. CF2018 as it turns out. runAsync. And this was also added to Lucee at some point too (their docs don't say when something was added).

I knocked together a quick repro of what I was looking at in spatie/async and JS as a baseline; and then wtote an equivalent in CFML. But when I ran it on Lucee it didn't seem to be behaving how I'd expect, but in a different way from what I was trying to compare to in the other languages. When I ran the same code on ColdFusion though, it seemed to behave the way I expected. It seemed I have found a Lucee rabbit hole to go down.

I ended up with this repro that demonstrates what I'm seeing. There's a chunk of code, but it's a bunch of largely the same operations repeated a few times so as to provide usable telemetry. I'll go through it piecemeal though.

This is all being run on Lucee 5.3.10.120.

start = getTickCount()
writeLog(file="runAsync", text="Begin @ #getTickCount() - start#")

I'll time things as I go.

writeLog(file="runAsync", text="f1 before define @ #getTickCount() - start#")
f1 = runAsync(() => {
    writeLog(file="runAsync", text="f1 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f1 after define @ #getTickCount() - start#")
  • I create a future
  • And it has a main task, and two then handlers.
  • Each of these do exactly the same thing:
    • Call a proc in the DB. See below for the implementation code, but you can probably tell it's a proc specifically designed to take time to execute. It's basically a DB-borne sleep call.
    • And log the current run time before and after the proc call.
  • Oh and I log the timing either side of the whole oepration too.

Here's the proc:

DROP PROCEDURE IF EXISTS sleep_and_return;
DELIMITER //
CREATE PROCEDURE sleep_and_return(IN seconds INT)
BEGIN
    DO SLEEP(seconds);
    SELECT seconds;
END //
DELIMITER ;

It just sleeps for the specified time and then returns the value it was passed.

Then I do exactly the same thing I did with f1 for f2 and f3 as well. Three identical sets of runAsync / then / then with the logging and the DB call.

After that, I sit back and get each of them, timing around each get:

writeLog(file="runAsync", text="f1 before get @ #getTickCount() - start#")
f1.get()
writeLog(file="runAsync", text="f1 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f2 before get @ #getTickCount() - start#")
f2.get()
writeLog(file="runAsync", text="f2 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f3 before get @ #getTickCount() - start#")
f3.get()
writeLog(file="runAsync", text="f3 after get @ #getTickCount() - start#")

And one final entry in the log at the end:

writeLog(file="runAsync", text="End @ #getTickCount() - start#")

All the code together looks like this:

start = getTickCount()
writeLog(file="runAsync", text="Begin @ #getTickCount() - start#")


writeLog(file="runAsync", text="f1 before define @ #getTickCount() - start#")
f1 = runAsync(() => {
    writeLog(file="runAsync", text="f1 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f1 after define @ #getTickCount() - start#")


writeLog(file="runAsync", text="f2 before define @ #getTickCount() - start#")
f2 = runAsync(() => {
    writeLog(file="runAsync", text="f2 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f2 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f2 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f2 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f2 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f2 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f2 after define @ #getTickCount() - start#")


writeLog(file="runAsync", text="f3 before define @ #getTickCount() - start#")
f3 = runAsync(() => {
    writeLog(file="runAsync", text="f3 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f3 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f3 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f3 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f3 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f3 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f3 after define @ #getTickCount() - start#")


writeLog(file="runAsync", text="f1 before get @ #getTickCount() - start#")
f1.get()
writeLog(file="runAsync", text="f1 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f2 before get @ #getTickCount() - start#")
f2.get()
writeLog(file="runAsync", text="f2 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f3 before get @ #getTickCount() - start#")
f3.get()
writeLog(file="runAsync", text="f3 after get @ #getTickCount() - start#")


writeLog(file="runAsync", text="End @ #getTickCount() - start#")

When I run this on CF2021, I get exactly what I'd expect:

Begin @ 0
f1 before define @ 1
f1 main before query @ 2
f1 after define @ 3
f2 before define @ 4
f2 main before query @ 6
f2 after define @ 8
f3 before define @ 10
f3 after define @ 12
f3 main before query @ 12
f1 before get @ 13
f1 main after query @ 1006
f1 then1 before query @ 1008
f2 main after query @ 1011
f2 then1 before query @ 1012
f3 main after query @ 1015
f3 then1 before query @ 1016
f1 then1 after query @ 2010
f1 then2 before query @ 2012
f2 then1 after query @ 2014
f2 then2 before query @ 2016
f3 then1 after query @ 2023
f3 then2 before query @ 2024
f1 then2 after query @ 3014
f1 after get @ 3016
f2 before get @ 3017
f2 then2 after query @ 3018
f2 after get @ 3020
f3 before get @ 3021
f3 then2 after query @ 3026
f3 after get @ 3028
End @ 3029

Each of the f1, f3, f3 operations are being executed in a "first come, first served", and independently of each other (ie: asynchronously). And it's all over and done with at about the time it takes the slowest one to finish (allowing for intrinsic overhead).

It's a different story when I run this on Lucee:

Begin @ 1
f1 before define @ 19
f1 main before query @ 24
f1 main after query @ 1244
f1 then1 before query @ 1247
f1 then1 after query @ 2252
f1 after define @ 2255
f1 then2 before query @ 2255
f2 before define @ 2255
f2 main before query @ 2258
f1 then2 after query @ 3258
f2 main after query @ 3263
f2 then1 before query @ 3266
f2 then1 after query @ 4270
f2 after define @ 4272
f3 before define @ 4273
f2 then2 before query @ 4274
f3 main before query @ 4276
f2 then2 after query @ 5277
f3 main after query @ 5278
f3 then1 before query @ 5281
f3 then1 after query @ 6284
f3 after define @ 6286
f3 then2 before query @ 6286
f1 before get @ 6286
f1 after get @ 6287
f2 before get @ 6288
f2 after get @ 6289
f3 before get @ 6290
f3 then2 after query @ 7288
f3 after get @ 7289
End @ 7290

Here f1 gets underway, but it really seems to mostly block until [f1 then2 before query] until f2 even gets a look-in. This is two seconds of synchronous execution before Lucee even finds out there's something else asynchronous to be cracking on with. Then f2 blocks for second before f3 gets a chance to be looked at. Then there's a mess of stopping and starting, sucking up even more time, for an end result of ~7sec for an "asynchronous" operation that would take ~9sec if it was synchronous. Not great.

I also hasten to add that this was not a case of bad luck how the "async-ness" happened to run this time. I've run this code dozens of times, and it's always around the same. I also have run it with just CFML's own sleep instead of the DB call, and it's still the same. It's not the work the tasks are doing, it's how Lucee is implementing the asynchronous thread management, I think.

Also if ColdFusion's handling of the same code was similar to Lucee's, I'd just chalk it up to "sometimes asynchronous code doesn't even up seeming that asynchronous". But given ColdFusion nails it, I really think there's something up with Lucee. Pity: I had a good use case for this stuff in our app. But now I'm thinking I need to go back to our simple <cfthread> implementations and check exactly how asynchronous that code is…

Full disclosure: I also found what seems to be a bug with how ColdFusion handles enclosed variable references asynchronously, but I can't work out what's going on with that yet, and I was half way through this bit of code, so I wanted to finish this first. I might come back to the ColdFusion thing "tomorrow".

The code here is reasonably portable (one just needs to create that proc, and a DSN), so I'd be dead keen to hear from other people if they can run it in their own Lucee environments, if you can be arsed, that is.

Or am I missing something? Entirely possible. Let me know.

Righto.

--
Adam

Thursday, 11 August 2022

Lucee: Creating a log file programmatically

G'day:

This will be super short as there's not much to say, I just want to note the code down for posterity, and to cross-reference elsewhere.

We need to create some log files in our application. I knew in ColdFusion one can just create a file ad-hoc, thus:

writeLog(file="anythingYouLike", text="some log message")

However the Lucee docs for writeLog were claiming that the file option was not implemented, and was also deprecated (this has since been rectified in the docs). It actually is implemented, but I was not so sure about the deprecation status. I asked and got no straight answer really. Anyway, the docs now say it's all good, so that's something.

Whilst this works, the log file is not managed by Lucee: it doesn't show up in Lucee Admin, so one cannot set things like log level / file size / file retention etc. This is fine for some situation, but was not fine for us. We need to be able to control the log level.

I had a sniff around, and found org.lucee.cfml.Administrator, and looking some more, found Configure Lucee within your application. From that, I concocted this proof of concept:

local.admin = new Administrator("web", server.system.environment.ADMINPASSWORD)
admin.updateLogSettings(
    name = "AdamTest",
    level = "ERROR",
    appenderClass = "lucee.commons.io.log.log4j2.appender.ResourceAppender",
    layoutClass = "lucee.commons.io.log.log4j2.layout.ClassicLayout",
    appenderArgs = {
        maxfiles = 20,
        maxfilesize = 1073741824
    }
)
writeLog(log="AdamTest", type="ERROR", text="ERROR SHOULD BE LOGGED")
writeLog(log="AdamTest", type="INFO", text="INFO SHOULD NOT BE LOGGED")

And - hurrah - this does exactly what it looks like it does: all the settings are set correctly and respected. Most importantly for us is that the log level works: in this case logging an ERROR works, but any logs at level INFO are not logged. We have some debugging stuff we want to leave log entries in the codebase, but in general set the log to be ERROR so they don't log until we need to do some debugging.

I had to guess at the appenderArgs key values, but on a whim I assumed they'd be the same as the form fields in Lucee admin, and they kinda were:

<input name="custom_3_appender_maxfiles" type="text" class="large" value="0">
<!-- … -->
<input name="custom_3_appender_maxfilesize" type="text" class="large" value="16">

It also shows up in Admin correctly:

Perfect.

And that's all I have to say on this.

Righto.

--
Adam

Monday, 2 May 2022

CFML: with Lucee, true isn't necessarily the same as true

G'day:

Yesterday I decided to improve my "Tiny Test Framework". I wrote an article about developing the first iterationof this as a TDD exercise six or so months ago: "TDD: writing a micro testing framework, using the framework to test itself as I build it". I use this framework on trycf.com, so I can include tests in my code samples. The first iteration of this only had the one toBe matcher, and yesterday I decided to add in toBeTrue, toBeFalse and toThrow: just to make my sample code on trycf a bit clearer.

Whilst implementing the toBeTrue matcher, I had a brain fart and ended up with this:

if (actual === true) {
    return true
}

This was the wrong approach to start with, and I'm too explicit in my check. I don't wanna be using the === operator there, this should be sufficient:

if (actual) {
    return true
}

IN CFML "truthy" should be enough for this matcher, as that's idiotmatic-CFML.

But whilst running my tests, I noticed something weird in Lucee. I had a test along these lines:

it("a passing test", () => {
    x = "something"
    expect(x.equals(x)).toBeTrue()
})

On ColdFusion, this passed fine.

But on Lucee, it failed. It seemed that apparently the same string doesn't equal itself. Although the more I dug, the weirder it got. I distilled a repro case down to:

s = "there can be only one"    
writeOutput(s.equals(s) === true) // Lucee: false; ColdFusion: true

This completely flummoxed me, and I posted something on the CFML Slack channel about it. Jonas Eriksson pointed me in the direction of an article on the topic of === that Ben had written a coupla years ago("Exploring The Triple Equals (===) Operator In Lucee CFML 5.3.4.77"). The article itself didn't tell me anything I didn't already "know" (ahem), but Brad's comment reminded me that Lucee's implementation of === is a bit shit. There's a Jira ticket for it here: "LDEV-1282: Fix === operator to check for type equality", and another one "LDEV-3132: ACF2021 - Identity/Not Identity Operator" that I have even participated in. Just a week ago!!.

The issue is that Lucee has decided to make the === operator to be an identity operator. IE: it does not do an equality and type check like ColdFusion does (full disclosure: Lucee implemented this operator before ColdFusion did), it just checks that the two operands are exactly the same object (ie: in memory).

How is this causing my problem? Well it's because not all trues are created equal, in Lucee. This gist demonstrates it:

system=createObject("java", "java.lang.System")    
    
s = "there can be only one"

e = s.equals(s)

t = true

writeDump([
    "e" = e, // true
    "t" = t, // true
    "==" = e == t, // true
    "===" = e === t, // LUCEE: FALSE; ColdFusion: true
    "e hashcode" = system.identityHashCode(e), // one thing, eg 712659136
    "t hashcode" = system.identityHashCode(t) // a different thing, eg: 558076530
])

Notice how the identity hashes for e and t are different. Therefore e === t is false on Lucee. This, I'm afraid, makes the === operator on Lucee about as useful as a chocolate teapot. In CFML it's really not important that a value occupies the same memory; but sometimes it's handy - because CFML is a loosely- & dynamically-typed language - to be able to check a value is the same and that it's actually the same type too (eg:"1" is equal to 1, but is not the same type). And this lack of joined-up-thinking in Lucee is demonstrated pretty clearly in that two instances of true are not considered the same as each other. That's just daft.

Out of interest I decided to push the boat out on my largely non-existent Java skills, check what Java does here. I came up with this:

class TestIdentiyEquality {

    public static void main(String[] args) {
        Boolean b1 = new Boolean(true); // deprecated approach to getting a Boolean
        Boolean b2 = new Boolean(true);

        System.out.println(String.format("via constructor, using equals: %b", b1.equals(b2))); // true 
        System.out.println(String.format("via constructor, using ==: %b", b1 == b2)); // false

        Boolean b3 = Boolean.parseBoolean("true");
        Boolean b4 = Boolean.valueOf("true");

        System.out.println(String.format("via parseBoolean/valueOf, using equals: %b", b3.equals(b4))); // true 
        System.out.println(String.format("via parseBoolean/valueOf, using ==: %b", b3 == b4)); // true
    }

}

It's interesting that in Java, creating a new Boolean object via its constructor is deprecated these days, in favour of using static methods that return the same Boolean each time. I guess this is Lucee's problem too: its true isn't the same object as the one the JVM is using (I presume internally Java uses the same object all over, but can't be arsed thoroughly checking this). Either way, Lucee have claimed that they have followed Java's route for the identity operator, which I think is odd given Java doesn't distinguish between value equality and identity equality via operators; it uses the equals method for checking value, and it only has the == operator other than that, and that does do an identity check. Also Java has no need to differentiate between "value equality" and "value and type equality" because it's a strongly typed language. It's not routine in Java to need to do myStringContaining1 == myNumericContaining1 like one would in a loosely typed language like CFML.

I did a check of some other languages that operate in a similar space to CFML (this is being a bit kind to CFML, but hey). My findings were:

  • Lucee, Python, Groovy, Kotlin treat === as reference equality check
  • CF, PHP, JS, Ruby treat it as a value & type check (in Ruby even == checks type too)

The code for the comparisons is in this gist.

I think CFML more closely fits with PHP, JS and - to a lesser extent - Ruby here, and I think ColdFusion has got the implementation of === right. Lucee should sort theirs out to work the same.


Oh, and where did I get to with my improvements to my tiny testing framework? This Twitter message sums-up my afternoon:

I spent so much time looking at various bugs in Lucee and spilling over into ColdFusion as I checked my code for the Lucee problem and found other bugs on ColdFusion too that I lost the taste for doing CFML, and just drank beer instead. It's a better use of my time, I think. The same could be applied to writing daft blog articles, so I'm off to find a beer instead.

Righto.

--
Adam


Update

OKOK, I did check what Java does about comparing two different true expressions:

class TestEquals {

    public static void main(String[] args) {
        String s1 = "there can be only one";
        String s2 = "maybe there can be another one, actually";
        Boolean b1 = s1.equals(s1);
        Boolean b2 = s2.equals(s2);

        System.out.println(String.format("b1: %b; b2: %b; b1 == b2: %b", b1, b2, b1 == b2)); // b1: true; b2: true; b1 == b2: true
    }

}

The equivalent in CFML is:

s1 = "there can be only one"
s2 = "maybe there can be another one, actually"
b1 = s1.equals(s1)
b2 = s2.equals(s2)

writeOutput("b1: #b1#; b2: #b2#; b1 == b2: #b1 === b2#") // b1: true; b2: true; b1 == b2: false (true on ColdFusion)

Even in the context of booleans "we do it how Java does it" doesn't stand-up to too much scrunity with Lucee. I think its implementation is just wrong.

Sunday, 17 April 2022

A day in the life of trying to write a blog article in the CFML ecosystem

G'day:

This is not the article I intended to write today. That article was gonna be titled "CFML: Adding a LogBox logger to a CFWheels app via dependency injection", but I'll need to get to that another day now.

Here's how far that article got before the wheels fell off:

And that was it.

Why? Well I started by writing an integration test just to check that box install logbox did what I expected:

import test.BaseSpec
import logbox.system.logging.LogBox

component extends=BaseSpec {

    function run() {
        describe("Tests the LogBox install", () => {
            it("is instantiable", () => {
                expect(() => getComponentMetadata("LogBox")).notToThrow()
            })
        })
    }
}

Simple enough. It'll throws an exception if LogBox ain't there, and I'm expecting that. It's a dumb test but it's a reasonable first step to build on.

I run the test:

Err… come again? I ain't installed it yet. I lifted the code from the expect callback out and run it "raw" in the body ofthe test case: predictable exception. I put it back in the callback. Test passes. I change the matcher to be toThrow. Test still passed. So this code both throws and exception and doesn't throw an exception. This is pleasingly Schrödingeresque, but not helpful.

The weird thing is I know this is not a bug in TestBox, cos we use notToThrow in our tests at work. I port the test over to my work codebase: test fails (remember: this is what I want ATM, we're still at the "red" of "red-green-refactor").

I noticed that we were running a slightly different version of Testbox in the work codebase: 4.4.0-snapshot compared to my 4.5.0+5. Maybe there's been a regression. I changed my TestBox version in box.json and - without thinking things through - went box install again (not just box install testbox which is all I really needed to do), and was greeted with this:

That's reasonably bemusing as I had just used box install fw1 to install it in the first place, and that went fine. And I have not touched it since. I checked what version I already had installed (in framework/box.json), and it claims 4.3.0. So… ForgeBox… I beg to differ pal. You found this version y/day, why can't you find it today? I check on ForgeBox, and for 4.x I see versions 4.0.0, 4.1.0, 4.2.0, 4.5.0-SNAPSHOT. OK, so granted: no 4.3.0. Except that's what it installed for me yesterday. Maybe 4.3.0 has issues and got taken down in the last 24h (doubtful, but hey), so I blow away my /framework directory, and remove the entry from box.json, and box install fw1 again. This is interesting:

root@280d80cf28c6:/var/www# box install fw1
√ | Installing package [forgebox:fw1]
|------------------------------------------------
| Verifying package 'fw1' in forgebox, please wait...
| Installing version [4.2.0].

4.2.0. But its entry in its own box.json is 4.3.0, and the constraint it put in my box.json is ^4.3.0.

I do not have time or inclination for any of this, so I just stick a constraint of ~4.2.0 in my box.json, and that seems to have solved it. I mean the error went away: it's still installing 4.3.0. Even with a hard-coded 4.2.0 it's still installing 4.3.0.

Brad Wood from Ortus/CommandBox had a look at this, nutted-out that there was something wrong with the way the FW/1 package on ForgeBox was configured, and he in turn pinged Steve Neiland who looks after FW/1 these days, and he got this sorted. I'm now on 4.3.0, and it says it's 4.2.0. And box install no longer complains at me. Cheers fellas.

Then I noticed that because of the stupid way CFWheels "organises" itself in the file system, I have inadvertantly overwritten a bunch of my own CFWheels files. Sigh. CFWheels doesn't bother to package itself up as "app" (its stuff) and "implementation" (my code that uses their app), it just has "here's some files: some you should change (anything outside the wheels subdirectory), some you probably shouldn't (the stuff in the wheels subdirectory)", but there's no differentiation when it comes to installation: all the files are deployed. Overwriting all the user-space files with their original defaults. Sorry but this is just dumbarsey. Hurrah for source control and small commit iterations is all I can say, as I could just revert some files and I was all good.

Right so now I have the same version of TestBox installed here as in our app at work (remember how this was all I was tring to do? Update testbox. Nothing to do with FW/1, and nothing to do with CFWheels. But there's an hour gone cocking around with that lot).

And the test still doesn't work. Ballocks.

I notice the Lucee version is also different. We're locked into an older version of Lucee at work due to bugs and incompats in newer versions that we're still waiting on to be fixed, so the work app is running 5.3.7.47, and I am on 5.3.8.206. Surely it's not that? I rolled my app's Lucee version back to 5.3.7.47 and the test started failing (correctly). OK, so it's a Lucee issue.

I spent about an hour messing around doing a binary search of Lucee container versions until I identified the last version that wasn't broken (5.3.8.3) and the next version - a big jump here - 5.3.8.42 that was broken. I looked at a diff of the code but nothing leapt out at me. This was slightly daft as I had no idea what I was looking for, so that was probably half an hour of time looking at Lucee's source code in an aimless fashion. I actually saw the change that was the problem, but didn't clock that that is what caused it at the time.

Having drawn a blank, I slapped my forehead, called myself a dick, and went back to the code in TestBox that was behaving differently. That would obviously tell me where to look for the issue.

I tracked the problem down to here, in system/Assertion.cfc:

    // Message+Detail regex must not match
    if (
        len( arguments.regex ) AND
        (
            !arrayLen( reMatchNoCase( arguments.regex, e.message ) ) OR !arrayLen(
                reMatchNoCase( arguments.regex, e.detail )
            )
        )
    ) {
        return this;
    }

    fail( arguments.message );
}

I distilled that down into a portable repro case:

s = ""
pattern = ".*"
writeDump([
    reMatch = s.reMatchNoCase(pattern),
    matches = s.matches(pattern),
    split = s.split(pattern)
])

There are some Java method calls there to act as controls, but on Lucee's current version, we get this:

And on earlier versions it's this:

(Full disclosure: I'm using Lucee 4.5 on trycf.com for that second dump, but it's the same results in earlier versions of Lucee 5, up to the point where it starts going wrong)

Note how previously a regex match of .* matches an empty string? This is correct. It does. In all regex engines I know of. Yet in Lucee's current versions, it returns a completely empty array. This indicates no match, and it's wrong. Simple as that. So there's the bug.

I was pointed in the direction of an existing issue for this: LDEV-3703. Depsite being a regression they know they caused, Lucee have decided to only fix it in 6.x. Not the version they actually broke. Less than ideal, but so be it.

There were a coupla of Regex issues dealt with between those Lucee versions I mentioned before. Here's a Jira search for "fixversion >= 5.3.8.4 and fixversion < 5.3.8.42 and text ~ regex". I couldn't be arsed tracking back through the code, but I did find something in LDEV-3009 mentioning a new Application.cfc setting:

this.useJavaAsRegexEngine = true

This is documented for ColdFusion in Application variables, and… absolutely frickin' nowhere in the Lucee docs, as far as I can see.

On a whim I stuck that setting in my Application.cfc and re-ran the test. If the setting was false: the test doesn't work. If it was true: the test does work. That's something, but Lucee is not off the hook here. The behaviour of that regex match does not change between the old and new regex engines! .* always matches an empty string! So there's still a bug.

However, being pragmatic, I figured "problem solved" (for now), and moved on. For some reason I restarted my container, and re-hit my tests:

I switched the setting to this.useJavaAsRegexEngine = false and the tests ran again (failed incorrectly, but ran). So… let me get this straight. For TestBox to work, I need to set that setting to true. To get CFWheels to work, I need to set it to false.

For pete's sake.

As I said on the Lucee subchannel on the CFML Slack:

Do ppl recall how I've always said these stupid flags to change behaviour of the language were a fuckin dumb idea, and are basically unusable in a day and age where we all rely on third-party libs to do our jobs?

Exhibit. Fucking. A.

Every single one of these stupid, toxic, setting doubles the overhead for library providers to make their code work. I do not fault TestBox or CFWheels one bit here. They can't be expected to support the exponential number of variations each one of those settings accumulates. I can firmly say that no CFML code should ever be written that depends on any of these settings. And no library or third-party code should ever be tested with the setting variation on. Just ignore them. The settings should not exist. Anyway: this is an editorial digression. "We are where we are" as the over-used saying goes.


Screw all this. Seriously. All I wanted to do is to do a blog article about perhaps 50-odd new lines of code in my example app. Instead I spent four hours untangling this shite. And my blog article has not progressed.

Here's what I needed to do to my app to work around these various issues:

This is all committed to GitHub as 0.5.1

Writing this sure was cathartic. I think I was my own audience for this one. Ah well. Good on you if you got to here.

Righto.

--
Adam

Monday, 17 January 2022

If your company (or yourself) makes money using Lucee… you should throw them a bone

G'day:

A few weeks back, right in the thick of the crap about all these Log4J vulnerabilities, I was talking to a few people about the necessity and the effort involved in Lucee getting their situation sorted out, vis-a-vis dealing with outdated library dependencies they had. They were lucky to be safe from the Log4J thing… but only serendipitously-so because they'd not been able to prioritise moving off a really old version of Log4J (which didn't have the problematic code in it yet). They just didn't have the resources to do anything about it, when considering all the rest of the work that kept coming in. The crux of it was that they can only afford so much paid-for dev time, which means tough decisions need to be made when it comes to deciding on what to work on.

To their credit, they've now removed the old version of Log4J from the current version of Lucee 5.x, as well as in the upcoming 6.x, replacing it with the fully-patched current version.

I had a private chat with one of the bods involved in the behind-the-curtain parts of Lucee's going on. Initially they were berating me for being unhelpful in my tone (we agreed to disagree on that one. Well: we didn't agree on anything, on that note. We just moved on), but then got to talking about what to do to sort the situation out. They explained the lack of help they were getting on the project, both in the context of volunteer devs, but as well as lack of €€€ to be able to pay the devs that dedicate their time to the project. I said "you need to get something like Patreon!", and they quickly pointed out that they'd told me about this already, and indeed included the link to it that very conversation.

https://opencollective.com/lucee.

I had only glanced at the page, and had not clocked it wasn't just some page of their own website going on about donations, and I was also completely oblivious to the fact that "Open Collective" is a thing: it is indeed a Patreon-a-like thing.

Cool. Good to know.

This also got me thinking. It sux that people are so happy to use things like Lucee for free, whilst lining their own pockets. Even worse when things don't go their own way, or they need something done, and expect it to just magically appear for them.

It also occurred to me that whilst I personally don't use Lucee to benefit me (although I indirectly do, I know), I sure work for a company that has built its software on Lucee, and is doing pretty well for itself. And I'm the one who's supposedly stewarding our development effort on Lucee, so I was being a bit of a hypocrite. I was not happy with myself about that. I needed to wait for some dust to settle at the end of the year, and then I forgot for a week, but today I bounced the idea of becoming a Lucee sponsor to my boss (the one with the cheque book), and he took zero convincing that it was the right thing to do. He was basically saying yes before I'd finished my wee speech explaining why we really ought to.

And this is the thing. Fair dos if you're just a dev working in a Lucee shop. Like me, you might think it's not on you to put money their way. Or just can't afford it (also like me). But what you could do is mention it to yer boss that it's maybe something the company could do. The bottom rung of the corporate sponsorship is only US$100/month, and whilst that's not trivia for an individual: it's nothing to a company. Even a small one. It's also a sound investment. The more contributions they get, the more time they will be able to spend making sure Lucee is stable, improving, and moving forward. It's more likely a bug that is getting in your way gets fixed (I am not suggesting anyone starts lording "I sponsor you so fix my bug" over them; I just mean there'll be more dev work done, which means more bugs will get fixed). It's actually a good and sensible investment for your company as well. And if it's a sound investment for your employers: it's a sound investment for you too, if you like to continue getting a salary, or move on to another CFML shop after yer current gig. And all you need to do is ask a question.

So: call to action. Here's what I'd like you to do. If you work in a Lucee shop and yer not already sponsoring Lucee: grab that link I posted above, and drop yer boss a line and go "hey, we get a lot of benefit from these guys and it's probably the right thing to do to chuck a bit of money their way. We won't notice it, but it'll really help them". It's easy to sign up, and it's just a zero effort question to ask.

You'll feel better about yerself if you do.

Righto.

--
Adam

Sunday, 20 June 2021

Making the code from the previous article work on both ColdFusion and Lucee

G'day:

A quick one today. I showed just a ColdFusion-only solution to some code in my previous article the other day: "CFML: emulating query-of-query group-by with higher-order functions". I figured when coming up with the completed code in a runnable example, I should make it work on both platforms. Here it is.

<cfscript>
function getUngroupedRecords(required numeric rows) {
    createRows = (number) => repeatString(",", rows).listToArray(",", true)
    date = () => now().add("d", randRange(-365, 365))
    amount = () => randRange(1,10000) / 100

    fakedDbData = queryNew(
        "settlementDate,LongTermGainLoss,ShortTermGainLoss",
        "Date,Double,Double",
        createRows(rows).map((_) => [date(), amount(), amount()])
    )
    return fakedDbData
}
ungroupedRecords = getUngroupedRecords(20)
writeDump(ungroupedRecords)

groupedRecords = ungroupedRecords.reduce((grouped={}, row) => {
    y = row.settlementDate.year()
    m = row.settlementDate.month()
    key = "#y#-#m#"
    grouped[key] = grouped[key] ?: {stgl = 0, ltgl = 0}
    grouped[key].stgl = grouped[key].stgl + row.ShortTermGainLoss
    grouped[key].ltgl = grouped[key].ltgl + row.LongTermGainLoss

    return grouped
}).reduce(
    (records, key, values) => {
        records.addRow({
            month = key.listLast("-"),
            year = key.listFirst("-"),
            ltgl = values.ltgl,
            stgl = values.stgl
        })
        return records
    },
    queryNew("month,year,ltgl,stgl", "Integer,Integer,Double,Double")
).sort((r1, r2) => {
    yearDiff = r1.year - r2.year
    if (yearDiff != 0) {
        return yearDiff
    }
    return r1.month - r2.month
})

writeDump(groupedRecords)
</cfscript>

Some notes on that:

  • I was using ColdFusion-only syntax for arrow functions with only one parameter: CF - correctly - does not require parentheses for the function signature here. Lucee however does, so I added them.
  • As previously-mentioned, Lucee didn't like arrayNew(1).resize(number) here, so I've changed it to being a bit shit, but at least it works on Lucee.
  • Lucee still doesn't return the updated query from Query.addRow, it returns the number of rows added (as per queryAddRow). ColdFusion changed this back in CF2018, so Lucee has some catch-up to do here. Anyway I needed to split this into two statements to make it work on Lucee.
  • Originally I had the sort callback as one expression to demonstrate a "trick" with variable assignment expressions, but whilst this worked in Lucee, ColdFusion choked on it. The callback was: (r1, r2) => (yearDiff = r1.year - r2.year) ? yearDiff : r1.month - r2.month. This pushed well past the bounds of what is clearly understandable, and I think the long-hand version I used is better code. But it was a bug in ColdFusion that the short version didn't work.

Anyway… this version of the code works on both ColdFusion and Lucee.

Righto.

--
Adam

Sunday, 30 May 2021

CFML: weirdness with… <cfquery> and single-quote escaping

G'day:

I was looking around for a good (read: bad) example of one of those exercises in "building a dynamic SQL string inside a <cfquery>". Firstly, one should pretty much never do this. You are almost certainly tightly-coupling business logic with DB-tier logic, and that's an anti-pattern right there. And it also means you can't test it without hitting an actual database, which is rubbish. So just: don't do it. Build the SQL string first, testing all the logic as you go, and once the string is built, pass the completed thing to queryExecute (let's all just pretend <cfquery> doesn't exist: it's a horrific construct, and should have been left to die in the C20th where it belongs).

I found an excellent example of this in the CFWheels codebase.

<cfquery attributeCollection="#arguments.queryAttributes#">

    <cfset local.$wheels.pos = 0>

    <cfloop array="#arguments.sql#" index="local.$wheels.i">

        <cfset local.$wheels.pos = local.$wheels.pos + 1>

        <cfif IsStruct(local.$wheels.i)>
            <cfset local.$wheels.queryParamAttributes = $queryParams(local.$wheels.i)>

            <cfif
                NOT IsBinary(local.$wheels.i.value)
                AND local.$wheels.i.value IS "null"
                AND local.$wheels.pos GT 1
                AND (
                    Right(arguments.sql[local.$wheels.pos-1], 2) IS "IS"
                    OR
                    Right(arguments.sql[local.$wheels.pos-1], 6) IS "IS NOT"
                )
            >
                NULL
            <cfelseif StructKeyExists(local.$wheels.queryParamAttributes, "list")>
                <cfif arguments.parameterize>
                    (<cfqueryparam attributeCollection="#local.$wheels.queryParamAttributes#">)
                <cfelse>
                    (#PreserveSingleQuotes(local.$wheels.i.value)#)
                </cfif>
            <cfelse>
                <cfif arguments.parameterize>
                    <cfqueryparam attributeCollection="#local.$wheels.queryParamAttributes#">
                <cfelse>
                    #$quoteValue(str=local.$wheels.i.value, sqlType=local.$wheels.i.type)#
                </cfif> 
            </cfif>
        <cfelse>
            <cfset local.$wheels.i = Replace(PreserveSingleQuotes(local.$wheels.i), "[[comma]]", ",", "all")>
            #PreserveSingleQuotes(local.$wheels.i)#
        </cfif>
        #chr(13)##chr(10)#
    </cfloop>
    <cfif arguments.limit>
        LIMIT #arguments.limit#
        <cfif arguments.offset>
            #chr(13)##chr(10)#
            OFFSET #arguments.offset#
        </cfif>
    </cfif>
    <cfif Len(arguments.comment)>
        #arguments.comment#
    </cfif>
</cfquery>

(note that in the CFWheels codebase, that is all one single line of code, which I find to be… astonishing)

Also note that there are more "opportunities for improvement" there than just embedding very complicated string-building logic into a DB call. But it's a perfect example of what I'm talking about. And it's by no means the only example I've seen of this; it's all over the place in the CFML world. In its defence, at least the logic here is not really business logic; it's all SQL-string-building-logic. So it could be homed close to the DB call - maybe even a private method the same class - but it def doesn't belong inline like that.

Why? Because it's really complicated, ought to have been developed using TDD strategies, but to test this logic, one needs to actually hit a database, because all the logic is munged into the DB call! Ugh.

I thought to myself "but it's so easy to have built this in a purposeful string-builder method; I wonder why it wasn't done that way?". There's a coupla things that offer a challenge to this:

  • it's slinging the parameter values inline with <cfqueryparam> which is a bit "old skool", and also hasn't been necessary since CF11 (and its Railo / Lucee counterparts), provided one uses queryExecute which can correctly separate the SQL statement from the parameters for the statement.
  • It's got that preserveSingleQuotes in there.

preserveSingleQuotes is harder to deal with. Firstly a refresher. For some reason best known to someone at Allaire, all single quotes in any expressions within <cfquery> tags are automatically escaped. Whether appropriate to do so or not. To prevent this from happening, one needs to wrap the expression with a call to preserveSingleQuotes. But this only works if the call to preserveSingleQuotes is made within the <cfquery> tag. One cannot use preserveSingleQuotes outside that context (something not mentioned in any of the ColdFusion, Lucee or CFDocs, btw). This is such a daft thing for ColdFusion to have instigated. <cfquery> should just pass the string it's given to the DB. The end. If there's an expression within the SQL string that has single quotes that need to be escaped, then the code building the SQL string should do the escaping. Do it when it's needed. Don't do it unilaterally and then provide a mechanism to not do it. Blimey.

Anyway, that means that with all that string-building logic within that <cfquery>, it's not just a matter of lifting the string out into its own method, and building it in a (unit) testable fashion.

This got me looking at a way of stopping <cfquery> from escaping stuff, so that the preserveSingleQuotes call ain't needed.

Lucee provides a tag attribute on <cfquery> to disable it: psq, which if false, will not do the escaping. I do so wish they'd put more thought into the naming of that, but hey. Maybe escapeSingleQuotes or something. Not just a mostly meaningless TLA. Ah well: at least it's there and it works.

ColdFusion implements no such functionality, as far as I can tell.

During my googling as to how to address this, I came across one of my own old articles: "UnexpectedBuggy ColdFusion behaviour with CFML statements in <cfquery> tags". And within the grey box down at the bottom, there was mention of using UDFs within a <cfquery> tag varying the behaviour of quote-escaping. Then I thought… "hang on a sec…?" and tried an experiment.

Here's a baseline example showing the problem CFML causes for itself with quote escaping:

<cfscript>
numbers = queryNew("id,en,mi", "integer,varchar,varchar", [
    [1,"one","tahi"],
    [2,"two","rua"],
    [3,"three","toru"],
    [4,"four","wha"],
    [5,"five","rima"],
    [6,"six","ono"],
    [7,"seven","whitu"],
    [8,"eight","waru"],
    [9,"nine","iwa"],
    [10,"ten","tekau"]
])

sqlStatement = "
    SELECT *
    FROM numbers
    WHERE mi IN ('rua', 'toru', 'rima', 'whitu')
"
</cfscript>

<cftry>
    <cfquery name="primes" dbtype="query">#sqlStatement#</cfquery>
    <cfset dump =  primes>
    <cfcatch>
        <cfset dump = [cfcatch.message, cfcatch.detail, cfcatch.extendedinfo]>
    </cfcatch>
    <cffinally>
        <cfdump var="#dump#" label="no handling">
    </cffinally>
</cftry>

Here my SQL string has single quotes in it. It's supposed to have. They're legit. That's syntactically correct. But ColdFusion (and Lucee, but I'm showing this on ColdFusion) thinks it knows better, and messes it up:

It's "helpfully" escaped all the single quotes for me. Thus breaking the SQL statement. Cheers for that.

I can prevent this from happening by using preserveSingleQuotes:

<cfquery name="primes" dbtype="query">#preserveSingleQuotes(sqlStatement)#</cfquery>

Fine. And in reality, this could almost certainly be the way CFWheels handles the string building exercise. Build the string in a string builder method, then preserveSingleQuotes the whole lot.

But what's this thing about UDFs messing with stuff. This is the thing that kinda surprises me. Check this out:

<cfscript>
    function returnTheArgument(theArgument) {
        return theArgument
    }
</cfscript>

<!--- ... --->
<cfquery name="primes" dbtype="query">#returnTheArgument(sqlStatement)#</cfquery>
<!--- ... --->

This… works. My function doesn't do anything… but simply calling it on the SQL statement inline within the <cfquery> tags is enough to prevent the CFML engine from escaping any single quotes.

W … T.a. … F?

And this works on both CF and Lucee.


Anyway. That's "interesting". My conclusion as to how to solve the problem with the embedded preserveSingleQuotes thing is probably to just not embed it into the middle of things; just to wrap the whole statement with them. Which means all that nasty untestable logic can be lifted out of being inline there, and put in its own function that does the one thing. "Single Responsibility Principle" craziness, I know. But the road to this conclusion today was a winding one, that's for sure.

[mutters to self] I dunno what the CFML engines are thinking here. I really don't.

Righto.

--
Adam

Thursday, 6 May 2021

Lucee: what now for goodness sake

G'day:

I'm just writing this here because it's too long to put in a message in the CFML/Lucee Slack channel, and so I can get some eyes on it.

Consider this code (test.cfm):

<cfoutput>
<cfset relativeFilePath = "../getCanonicalPathIssue/targetfile.cfm">
Relative file path: [#relativeFilePath#]<br>
Does relative path exist: [#fileExists(relativeFilePath)#]<br>
<br>

<cfset expandedPath = expandPath(relativeFilePath)>
Expanded file path: [#expandedPath#]<br>
Does expanded path exist: [#fileExists(expandedPath)#]<br>
<br>

<cfset canonicalPathFromRelativeFilePath = getCanonicalPath(relativeFilePath)>
Canonical path from relative path: [#canonicalPathFromRelativeFilePath#]<br>
Does canonical pathh from relative path exist: [#fileExists(canonicalPathFromRelativeFilePath)#]<br>
<br>

<cfset canonicalPathFromExpandedPath = getCanonicalPath(expandedPath)>
Canonical path from expanded path: [#canonicalPathFromExpandedPath#]<br>
Does canonical path from expanded path exist: [#fileExists(canonicalPathFromExpandedPath)#]<br>
<br>

<cfset directory = getDirectoryFromPath(canonicalPathFromRelativeFilePath)>
Directory: #directory#<br>
Directory contents and do they exist:<br>
#directoryList(directory).reduce((buffer="", filePath) => buffer & "#filePath#: #fileExists(filePath)#<br>")#
</cfoutput>

And this is its output:

Relative file path: [../getCanonicalPathIssue/targetfile.cfm]
Does relative path exist: [false]

Expanded file path: [/var/www/public/nonWheelsTests/getCanonicalPathIssue/targetfile.cfm]
Does expanded path exist: [true]

Canonical path from relative path: [/var/www/public/nonWheelsTests/getCanonicalPathIssue/targetFile.cfm]
Does canonical path from relative path exist: [false]

Canonical path from expanded path: [/var/www/public/nonWheelsTests/getCanonicalPathIssue/targetfile.cfm]
Does canonical path from expanded path exist: [true]

Directory: /var/www/public/nonWheelsTests/getCanonicalPathIssue/
Directory contents and do they exist:
/var/www/public/nonWheelsTests/getCanonicalPathIssue/test.cfm: true
/var/www/public/nonWheelsTests/getCanonicalPathIssue/targetfile.cfm: true

Basically I've got a second file (targetfile.cfm) in the same directory as I'm running this code from (test.cfm), and I'm giving Lucee a (valid) relative path to it, and asking some questions. Everything goes OK until I get to the result of getCanonicalPath(relativeFilePath): it's upper-cased part of the file name!??! Also note that expandPath(relativeFilePath) gets it right. And that getCanonicalPath(expandedPath) also gets it right.

The last bit of the code just shows what's def in the directory concerned.

I actually know what's causing the problem. A coupla hours ago I renamed the file from targetFile.cfm to targetfile.cfm. note the change in capitalisation, and how the old version matches the bad value getCanonicalPath is coming up with. So Lucee is caching that for some reason. I also found where to uncache it, but am buggered if I know why this setting caches file paths:

That's supposed to be about how often the contents of the file are checked; nothing about file paths. But if I set it to "Always (Bad)", then the problem goes away. It's clearly this lesser used definition of "bad", that means "actually works".

So that's an hour or so of my life I'll never get back. Thanks.


For shits and giggles I decided to run this on ColdFusion:

I'd give ColdFusion a pass here for choking on a relative path if not for two things:

  • it's specifically documented as dealing with them: "Absolute or relative path of a directory or to a file."
  • The path is a valid relative path. There's no trickery with the casing going on here, or caching or anything like that. The relative path I'm providing is the path to that file, relative to where the path is being used.

Oh well. I suppose I'll check with ppl to see if there's a reason why this behaviour on each platform, isn't wrong in the way I claim it is… and then raise some bugs. I'll cross ref once I've done that, but it'll be tomorrow now.

Righto.

--
Adam

Tuesday, 4 May 2021

abort! abort;!

G'day

What do you (CFMLers, sorry) make of this?

<cfscript>
function f(){
    writeOutput("in f<br>")
    abort
}

writeOutput("before f<br>")
f()
writeOutput("after f<br>")
</cfscript>

What would you expect that to output? The foolhardly money would go on:

before f
in f

Because, like, it's obvious: after f is never called because we're aborting in the function. Right?

Well yer partly right. On ColdFusion, that's exacly what happens (I tested on CF2021). On Lucee, however, I get this:

before f
in f
after f

Um… kewl.

The thing is that if one adds a semi-colon after the abort, Lucee starts behaving.

<cfscript>
function f(){
    writeOutput("in f<br>")
    abort;
}

writeOutput("before f<br>")
f()
writeOutput("after f<br>")
</cfscript>

I had some abort-confusion the other day on the CFML / Lucee Slack channel because this had behaviour I did not expect:

But that's actually correct behaviour. abort takes an optional string parameter showError, and writeOutput returns true (don't ask), which can be coerced into a string. If a statement has only one parameter, its name can be omitted, so Lucee is interpretting that as a multi-line abort statement - with a showError value of true - that doesn't end until the explicit semi-colon.

This is not the same though, as far as I can tell. The } of the function block is an explicit end-of-statement token just like a semi-colon is. Or at least it ought to be.


In other news, this sample code won't run correctly on trycf.com, which you can check out at https://trycf.com/gist/759318ea257c7ca7130c1f12c3ee72f8: Lucee doesn't work as expected whether or not the semi-colon is there; and CF only works as expected when the semi-colon is not there. This is at odds to how it works on (my) actual servers. I'd be interested in what behaviour you get on your servers?

Am still wondering a bit if I'm missing something here; especially given the different varieties of behaviour…

Righto.

--
Adam

Sunday, 25 April 2021

Misc changes to environment for my ongoing Docker / Lucee / CFWheels series

G'day

This will be a bit of a scrappy article just summarising some changes to my project environment since the last article in this series on Lucee / CFWheels / Docker; "Adding TestBox, some tests and CFConfig into my Lucee container". By the end of that article I'd got Nginx proxying calls to Lucee, and some tests to verify its integrity and my expectations of how it ought to be working. I'm about to continue with an article about getting CFWheels to work (URL TBC), but before that - and for the ake of full disclosure - I'll detail these wee changes I've made.

It can connect Lucee to a MariaDB database and fetch records

The test summarises the aim here. /test/integration/TestDatabaseConnection.cfc:

component extends=testbox.system.BaseSpec {

    function run() {
        describe("Tests we can connect to the database", () => {
            it("can retrieve test records", () => {
                expectedRecords = queryNew("id,value", "int,varchar", [
                    [101, "Test row 1"],
                    [102, "Test row 2"]
                ])

                actualRecords = queryExecute("SELECT id, value FROM test ORDER BY id")
                
                expect(actualRecords).toBe(expectedRecords)
            })
        })
    }
}

Note that this filed under test/integration because it's testing the integration between Lucee and the DB, rather than any business logic.

I've aded some config to the test suite's Application.cfc too:

component {

    this.mappings = {
        "/cfmlInDocker/test" = expandPath("/test"),
        "/testbox" = expandPath("/vendor/testbox")
    }

    this.localmode = "modern"

    this.datasources["cfmlInDocker"] = {
        type = "mysql",
        host = "database.backend",
        port = 3306,
        database = "cfmlindocker",
        username = "cfmlindocker",
        password = server.system.environment.MYSQL_PASSWORD,
        custom = {
            useUnicode = true,
            characterEncoding = "UTF-8"
        }
    }
    this.datasource = "cfmlInDocker"
}

One key thing to note here is that I am setting this.localmode in here. Previous I was setting this in Lucee's global config via CFConfig, but Zac Spitzer dropped me a line and pointed out it could be set at runtime in Application.cfc. This is a much more elegant approach, so I'm running with it.

Other than that I'm setting a data source. Note I'm picking up the password from the environment, not hard-coding it. This is passed by the docker-compose.yml file:

lucee:
    build:
        context: ./lucee
        args:
            - LUCEE_PASSWORD=${LUCEE_PASSWORD}
    environment:
        - MYSQL_PASSWORD=${MYSQL_PASSWORD}

For the implementation of this requirement I've added a Docker container for MariaDB, added a test table into it and tested that Lucee can read data from it. This was all straight forward. Here are the file changes:

/docker/mariadb/Dockerfile:

FROM mariadb:latest

COPY ./docker-entrypoint-initdb.d/ /docker-entrypoint-initdb.d/
COPY ./conf/logging.cnf /etc/mysql/conf.d/logging.cnf
RUN chmod -R 644 /etc/mysql/conf.d/logging.cnf

CMD ["mysqld"]

EXPOSE 3306

Nothing mysterious there. I'm using the entrypoint to create the DB table and populate it (docker-entrypoint-initdb.d/1.createAndPopulateTestTable.sql):

USE cfmlindocker;

CREATE TABLE test (
    id INT NOT NULL,
    value VARCHAR(50) CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci NOT NULL,

    PRIMARY KEY (id)
) ENGINE=InnoDB;

INSERT INTO test (id, value)
VALUES
    (101, 'Test row 1'),
    (102, 'Test row 2')
;

ALTER TABLE test MODIFY COLUMN id INT auto_increment;

I'm also moving logging to a different directory so I can see them on my host machine (via conf/logging.cnf):

[mysqld]
log_error = /var/log/mariadb/error.log

This is all wired-together in docker-compose.yml

mariadb:
    build:
        context: ./mariadb
    environment:
        - MYSQL_ROOT_PASSWORD=${DATABASE_ROOT_PASSWORD}
        - MYSQL_DATABASE=${MYSQL_DATABASE}
        - MYSQL_USER=${MYSQL_USER}
        - MYSQL_PASSWORD=${MYSQL_PASSWORD}
    ports:
        - "3306:3306"
    volumes:
        - mysqlData:/var/lib/mariadb
        - ./mariadb/root_home:/root
        - ../var/log:/var/log
    stdin_open: true
    tty: true
    networks:
        backend:
            aliases:
                - database.backend

volumes:
    mysqlData:

Note that I am sticking the DB data into a Docker volume instead of in a volume from my host machine. This means I need to take some care if I ever get around to adding non-test data into it, but for the time being it saves cluttering up my host machine with DB files, plus it's easier during initial configuration to completely reset the DB. It's easy enough to change later on when I need to.

I'm setting some of those magic environment variable in .env:

COMPOSE_PROJECT_NAME=cfml-in-docker
MYSQL_DATABASE=cfmlindocker
MYSQL_USER=cfmlindocker

# the following are to be provided to `docker-compose up`
LUCEE_PASSWORD=
DATABASE_ROOT_PASSWORD=
MYSQL_PASSWORD=

And the passwords when I build the containers:

adam@DESKTOP-QV1A45U:/mnt/c/src/cfml-in-docker/docker$ DATABASE_ROOT_PASSWORD=123 MYSQL_PASSWORD=1234 LUCEE_PASSWORD=12345 docker-compose up --build --detach --force-recreate

It got rid of CFConfig

Both the Lucee settings I needed to change with CFConfig before hand can be done natively with Lucee, so I didn't need CFConfig any more. I might need it again later, in which case I will re-install it. But for now it's dead-weight.

RUN box install commandbox-cfconfig
RUN box cfconfig set localScopeMode=modern to=/opt/lucee/web
RUN box cfconfig set adminPassword=${LUCEE_PASSWORD} to=/opt/lucee/web
RUN echo ${LUCEE_PASSWORD} > /opt/lucee/server/lucee-server/context/password.txt # this handles the passwords for both server and web admins

It can run the tests from the shell

Running TestBox's tests in a browser is all very pretty, but not very practical. Fortunately I read the TestBox docs some more and found out how to run them from the shell. They show how to run it from within CommandBox's own special shell here in "TestBox integration › Test runner", but that's weird and no help to me. However I finally twigged that it seems that whatever one might do within the special shell, one can also call from the normal shell via the box command. All I needed to do to enable this was to tell CommandBox how to run the tests in docker/lucee/box.json, which is used by CommandBox in the docker/lucee/Dockerfile:

{
    "devDependencies":{
        "testbox":"^4.2.1+400"
    },
    "installPaths":{
        "testbox":"vendor/testbox/"
    },
    "testbox":{
        "runner":"http://localhost:8888/test/runTests.cfm"
    }
}
COPY ./box.json /var/www/box.json
RUN mkdir -p /var/www/vendor
RUN box install

This has the benefit that the test run doesn't simply return a 200-OK all the time whether tests all passed or not; it exits with a 1 if there's any test failures. So it's usable in a CI/CD situation.

It resolves the slowness with CommandBox

In the previous article I observed that running stuff with CommandBox seemed to have about a 45sec overhead for any action. I tracked this down to the fact that I have my /root/home directory as a volume from my host machine so my various shell histories persist across container rebuilds. And I then realised that CommandBox dumps a whole lot of shite in that directory which it needs to load every time it runs. Because of the shenanigans Docker needs to do when bridging from its file system across to WSL across to the native Windows file systems, these operations are S-L-O-W. OK for a few files. Not OK for stacks of them.

Fortunately CommandBox can be configured to put its temp files elsewhere, so I have configured it to put them in /var/temp instead. As they regenerate if they are missing, this seems like the best place for them. It also prevents clutter leaking out of my container and onto my host machine. This is done via a commandbox.properties file:

commandbox_home=/var/tmp/commandbox

Which I copy into place in the Dockerfile. CommandBox picks it up automatically when I place it there:

COPY ./commandbox.properties /usr/local/bin/commandbox.properties

Good stuff. Now it only takes about 5sec for box to start doing anything, which is fine.

It no longer has the problem with path_info

I covered the shortfall in how Lucee handles path_info in "Repro for Lucee weirdness". I've managed to work around this. Kind of. In a way that solves the problem for this project anyhow.

Well I guess really it is just "learning to live with it". I've done some other experimentation with CFWheels, and all it uses path_info for is indeed to implement semi-user-friendly URLs tacked on to index.cfm. It has no need for any other .cfm file to use its path_info, so the default mappings are actually fine as they are.

However it occurred to me when I was configuring Nginx to do its part of the user-friendly URLs that all requests coming into Lucee from the web server will land in /public, so I could just put in a servlet mapping for the index.cfm in that directory (from web.xml):

<servlet-mapping>
    <servlet-name>CFMLServlet</servlet-name>
    <url-pattern>*.cfm</url-pattern>
    <url-pattern>*.cfml</url-pattern>
    <url-pattern>*.cfc</url-pattern>
    <url-pattern>/index.cfm/*</url-pattern>
    <url-pattern>/index.cfc/*</url-pattern>
    <url-pattern>/index.cfml/*</url-pattern>

    <url-pattern>/public/index.cfm/*</url-pattern>
</servlet-mapping>

One might think that instead of using <url-pattern>/public/index.cfm/*</url-pattern>, I might be able to just specify a match for the entire directory, like this: <url-pattern>/public/*</url-pattern>. From a POV of Tomcat's expectations this ought to be good enough, but from Lucee's perspective it doesn't see that as a "anything in that directory", it's expecting that pattern to be a file that matches a CFML file, so when I tried that I just got an error along the lines of "/public is a directory". Ah well. FWIW, ColdFusion said pretty much the same thing.

One downside to this is that I cannot work out how to add a servlet mapping just for this Lucee application, so I need to replace the entire Tomcat web.xml file, with another one with just one additional line (the original file is 4655 lines long). This is less than ideal, and I've followed it up on the Lucee Slack channel. I just copy the file over in the Dockerfile:


COPY ./root_home/.bashrc /root/.bashrc
COPY ./root_home/.vimrc /root/.vimrc
COPY ./web.xml /usr/local/tomcat/conf/web.xml

I had to rename my test file to index.cfm (so this means the test will need to just go once I install CFWheels which needs that file), but for now I was able to test the change:


it("passes URL path_info to Lucee correctly", () => {
    testPathInfo = "/additional/path/info/"

    http url="http://cfml-in-docker.frontend/index.cfm#testPathInfo#" result="response";

    expect(response.status_code).toBe(200, "HTTP status code incorrect")
    expect(response.fileContent.trim()).toBe(testPathInfo, "PATH_INFO value was incorrect")
})
<cfoutput>#CGI.path_info#</cfoutput>

Oh! And the Nginx changes! docker/nginx/sites/default.conf:

location / {
    try_files $uri $uri/ =404;
    try_files $uri $uri/ @rewrite;
}

location @rewrite {
    rewrite ^/(.*)? /index.cfm$request_uri last;
    rewrite ^ /index.cfm last;
}

(Thanks to the ColdBox docs for those)

It no longer needs PHP to test things

I'm happy that TestBox is working well enough now that I don't need to test things with PHPUnit, and that's all the PHP container was for, so I've removed all that stuff.


That's it. In the next article I shall continue from here, and get CFWheels set up in a waythat doesn't require the entire application being a) messed in with my own code; b) in a web browsable directory. Stay tuned…

Righto.

--
Adam