Monday, 18 April 2022

CFML: Adding a LogBox logger to a CFWheels app via dependency injection

G'day:

This follows on from CFML: implementing dependency injection in a CFWheels web site. In that article I got the DI working, but only with a test scenario. For the sake of completeness, I'm gonna continue with the whole point of the exercise, which is getting a logger service into my model objects, via DI.


0.6 adding LogBox

I ran into some "issues" yesterday whilst trying to write this article. Documented here: "A day in the life of trying to write a blog article in the CFML ecosystem", and there's some file changes committed as 0.5.1. So that killed my motivation to continue this work once I'd waded through that. I appear to be back on track now though.

Right so I'll add a quick test to check LogBox is installed. It's a bit of a contrived no-brainer, but this is playing to my strengths. So be it:

describe("Tests the LogBox install", () => {
    it("is instantiable", () => {
        expect(() => getComponentMetadata("LogBox")).notToThrow(regex="^.*can't find component \[LogBox\].*$")
    })
})

If LogBox is where it's supposed to be: it'll pass. Initially I had a new LogBox() in there, but it needs some config to work, and that requires a bit of horsing around, so I'll deal with that next. For now: is it installed? Test sez "no":

Test sez… yes.

OK. That was unexpected. Why did that pass? I have checked that LogBox is not installed, so WTH??

After a coupla hours of horsing about looking at TestBox code, I worked out there's a logic… um… shortfall (shall I say) in its implementation of that regex param, which is a bit wayward. The code in question is this (from /system/Assertion.cfc):

 if (
    len( arguments.regex ) AND
    (
        !arrayLen( reMatchNoCase( arguments.regex, e.message ) )
        OR
        !arrayLen( reMatchNoCase( arguments.regex, e.detail ) )
    )
) {
    return this;
}

Basically this requires both of message and detail to not match the regex for it to be considered "the same" exception. This is a bit rigorous as it's really unlikely for this to be the case in the real world. I've raised it with Ortus (TESTBOX-349), but for now I'll just work around it. Oh yeah, there's a Lucee bug interfering with this too. When an exception does have the same message and details, Lucee ignores the details. I've not raised a bug for this yet: I'm waiting for them to fee-back as to whether I'm missing something. When there's a ticket, I'll cross-post it here.

Anyway, moving on, I'll just check for any exception, and that'll do:

expect(() => getComponentMetadata("LogBox")).notToThrow()

That was a lot more faff to get to this point than I expected. Anyway. Now I install LogBox:

root@60d2920f4c60:/var/www# box install logbox
√ | Installing package [forgebox:logbox]

0.7 wiring LogBox into the DependencyInjectionService

One of the reasons the previous step really didn't push the boat out with testing if LogBox was working, is that to actually create a working LogBox logger takes some messing about; and I wanted to separate that from the installation. And also to give me some time to come up with the next test case. I want to avoid this sort of thing:

Possibly © 9gag.com - I am using it without permission. If you are the copyright owner and wish me to remove this, please let me know.

I don't want to skip to a test that is "it can log stuff that happens in the Test model object". I guess it is part ofthe requiremnt that the logger is handled via dependency injection into the model, so we can first get it set up and ready to go in the DependencyInjectionService. I mean the whole thing here is about DI: the logger is just an example usage. I think the next step is legit.

I've never used LogBox before, so I am RTFMing all this as I type (docs: "Configuring LogBox"). It seems I need to pass a Config object to my LogBox object, then get the root logger from said object… and that's my logger. Al of that can go in a factory method in configureDependencies, adn I'll just put the resultant logger into the IoC container.

it("loads a logger", () => {
    diService = new DependencyInjectionService()

    logger = diService.getBean("Logger")

    expect(logger).toBeInstanceOf("logbox.system.logging.Logger")

    expect(() => logger.info("TEST")).notToThrow()
})

I'm grabbing a logger and logging a message with it. The expectation is simply that the act of logging doesn't error. For now.

First here's the most minimal config I seem to be able to get away with:

component {
    function configure() {
        variables.logBox = {
            appenders = {
                DummyAppender = {
                    class = "logbox.system.logging.appenders.DummyAppender"
                }
            }
        }
    }
}

The docs ("LogBox DSL ") seemed to indicate I only needed the logBox struct, but it errored when I used it unless I had at least one appender. I'm just using a dummy one for now because I'm testing config, not operations. And there's nothing to test there: it's all implementation, so I think it's fine to create that in the "green" phase of "red-green-refactor" from that test above (currently red). With TDD the red phase is just to do the minimum code to make the test pass. That doesn't mean it needs to be one line of code, or one function or whatever. If my code needed to call a method on this Config object: then I'd test that separately. But I'm happy that this is - well - config. It's just data.

Once we have that I can write my factory method on DependencyInjectionService:

private function configureDependencies() {
    variables.container.declareBean("DependencyInjectionService", "services.DependencyInjectionService")
    variables.container.declareBean("TestDependency", "services.TestDependency")

    variables.container.factoryBean("Logger", () => {
        config = new Config()
        logboxConfig = new LogBoxConfig(config)

        logbox = new LogBox(logboxConfig)
        logger = logbox.getRootLogger()

        return logger
    })
}

I got all that from the docs, and I have nothing to add: it's pretty straight forward. Let's see if the test passes:

Cool.

Now I need to get my Test model to inject the logger into itself, and verify I can use it:

it("logs calls", () => {
    test = model("Test").new()
    prepareMock(test)
    logger = test.$getProperty("logger")
    prepareMock(logger)
    logger.$("debug")

    test.getMessage()

    loggerCallLog = logger.$callLog()
    expect(loggerCallLog).toHaveKey("debug")
    expect(loggerCallLog.debug).toHaveLength(1)
    expect(loggerCallLog.debug[1]).toBe(["getMessage was called"])
})

Here I am mocking the logger's debug method, just so I can check it's being called, and with what. Having done this, I am now wondering about "don't mock what you don't own", but I suspect in this case I'm OK because whilst the nomenclature is all "mock", I'm actually just spying on the method that "I don't own". IE: it's LogBox's method, not my application's method. I'll have to think about that a bit.

And the implementation for this is way easier than the test:

// models/Test.cfc
private function setDependencies() {
    variables.dependency = variables.diService.getBean("TestDependency")
    variables.logger = variables.diService.getBean("Logger")
}

public function getMessage() {
    variables.logger.debug("getMessage was called")
    return variables.dependency.getMessage()
}

Just for the hell of it, I also wrote a functional test to check the append was getting the expected info:

it("logs via the correct appender", () => {
    test = model("Test").new()

    prepareMock(test)
    logger = test.$getProperty("logger")

    appenders = logger.getAppenders()
    expect(appenders).toHaveKey("DummyAppender", "Logger is not configured with the correct appender. Test aborted.")

    appender = logger.getAppenders().DummyAppender
    prepareMock(appender)
    appender.$("logMessage").$results(appender)

    test.getMessage()

    appenderCallLog = appender.$callLog()

    expect(appenderCallLog).toHaveKey("logMessage")
    expect(appenderCallLog.logMessage).toHaveLength(1)
    expect(appenderCallLog.logMessage[1]).toSatisfy((actual) => {
        expect(actual[1].getMessage()).toBe("getMessage was called")
        expect(actual[1].getSeverity()).toBe(logger.logLevels.DEBUG)
        expect(actual[1].getTimestamp()).toBeCloseTo(now(), 2, "s")
        return true
    }, "Log entry is not correct")
})

It's largely the same as the unit test, except it spies on the appender instead of the logger. There's no good reason for doing this, I was just messing around.


And that's it. I'm pushing that up to Git as 0.7

… and go to bed.

Righto.

--
Adam