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

Using a decorator pattern to reduce inappropriate code complexity

G'day:
This one stemmed from a challenge we had with some code at work, and the thought exercise as to how it should have been resolved. Unfortunately the code in question is in a library our team needs to use, but didn't have any say in the design, plus it's out the door now so we're kinda stuck with it. However hopefully we can reduce the chance of this sort of thing happening again.

We use a variation of the Repository Pattern to interface between our application and whatever mechanism provides the data for it. Our philosophy is that an application's repositories with take data from [something] and model it into the domain objects our application wants to deal with. No storage considerations, or storage schema requirements should leak into the application: no table or column references, JSON (we use a bunch of web services for a lot of our data fetching), or the like. So our repositories are adapters. I dunno how closely this sticks to the letter of the pattern as per Microsoft's intent, but... shrug... it makes sense to us.

We'd typically have this sort of flow:

• a request is matched to a route;
• a route is handled by a controller;
• a controller calls one or more services to do whatever's necessary to fulfil the request;
• data is passed to a Twig template which creates the response mark-up.

Typical MVC sort of stuff. Sometimes we go straight from controller to repo if it's a situation that there's no real business logic, but this has proven dangerous because it's very rare there's no business logic, so even if our services just bridge between controller and repo: so be it. Note that a lot of our business logic is done by the remote services we call, as we are just one client application using these services; there are many others, so we keep the logic as close to the centre of shared operations as possible.

Also note as I alluded to above: our repos do not perform business logic. They simply transform data from the application-neutral format (or stoage-specific format) to the our-application-specific format.

A very simple use repository might be as follows:

class UserRepository {

    private $dataSource;

    public function __construct($dataSource) {
        $this->dataSource = $dataSource;
    }

    public function getById($id) {
        $userAsJson = $this->dataSource->getById($id);

        $rawUser = json_decode($userAsJson);
        $user = new User($rawUser->id, $rawUser->firstName, $rawUser->lastName);
    
        return $user;
    }

}

The repo is initialised with a connection to the storage mechanism, and all it does it ask the storage mechanism for some data, then rehydrate the returned raw data into a domain object for the application to use. This means the only part of the application which knows about how the data is exposed to the application is the repository. If we change our storage from being web-serviced based to being a direct connection to an SQL data store; we simply change the repository. The rest of our app stays the same. Nice.

A while back I encountered code similar to this (below). I hasten to add all the code in this article is purpose-written for this article, and any resemblance to our actual code is only so that I can demonstrate the point. Anyway, here's a user repository:

class UserRepository {

    private $dataSource;
    private $loggerService;
    private $cacheService;

    public function __construct($dataSource, $loggerService, $cacheService) {
        $this->dataSource = $dataSource;
        $this->loggerService = $loggerService;
        $this->cacheService = $cacheService;
    }

    public function getById($id) {
        $this->loggerService->logText("$id requested");

        if ($this->cacheService->isCached($id)) {
            return $this->cacheService->get($id);
        }

        $userAsJson = $this->dataSource->getById($id);
        $rawUser = json_decode($userAsJson);
        $user = new User($rawUser->id, $rawUser->firstName, $rawUser->lastName);

        $this->cacheService->put($id, $user);

        return $user;
    }

}

'ullo 'ullo 'ullo. What's going on here then? Now as well as going about its business as a user repository, our repo also seems to know about logging and caching. Logging and caching having nothing to do with the repo's job, yet now close to 50% of its code is dealing with these. And we've tightly coupled this functionality into the repo itself (at least its external services doing the actual work). Really now the UserRepository should be called a LoggedCachedUserRepository.

It also means that to have a working UserRepository, I also need to have working caching, and working logging Whether I actually want them or not. Soon after this code was introduced we had another situation to use the UserRepository, but it was in a a different context, and the logging and caching services weren't available (nor in this case needed or wanted). We could still negate them kinda by creating a null logger and a null cacher, along these lines:

class NullLoggerService {

    public function logText($text) {
        echo "NullLoggerService used<br>";
    }

}

class NullCacheService {

    public function __construct(){
    }
    
    public function isCached($key){
        return false;
    }
    
    public function get($key){
        throw new \Exception();
    }
    
    public function put($key, $value){
    }
        
}

That's "fine", and that "works", except it's even more code to maintain to actually do less stuff. All cos we tightly coupled caching and logging to the repo in the first place.

Also... logging and caching are business logic, so kinda violate our general usage pattern of repositories anyhow.

But in some situations we do actually want the caching tier, and we do actually want the logging tier. It was legit for those operations to be being run. It's just not legit for the code to be in the repository like that. So what ought we have done?

Use the decorator pattern.

Firstly, we leave our actual UserRepository to busy itself with doing UserRepository stuff.

class UserRepository implements UserRepositoryInterface {

    private $dataSource;

    public __construct($dataSource) {
        $this->dataSource = $dataSource;
    }

    public function getById($id) {
        $userAsJson = $this->dataSource->getById($id);

        $rawUser = json_decode($userAsJson);
        $user = new User($rawUser->id, $rawUser->firstName, $rawUser->lastName);
    
        return $user;
    }

}

Notice how I've added an interface requirement there. I'd normally not bother to do that, but it helps demonstrate the point. Our UserService now requires a RepositoryInterface object:

class UserService {

    private $userRepository;

    public function __construct(UserRepositoryInterface $userRepository) {
        $this->userRepository = $userRepository;
    }

    public function getById($id) {
        return $this->userRepository->getById($id);
    }
}

As long as it's a UserRepositoryInterface, it doesn't care how it goes about implementing it. Next we add a decorator to handle the logging, but to only handler the logging. It hands the user-getting task to a dependent UserRepository that knows how to do that. And of course we already have one of those! Here's the code:

class LoggedUserRepository implements UserRepositoryInterface {

    private $repository;
    private $loggerService;

    public function __construct(UserRepositoryInterface $repository, LoggerServiceInterface $loggerService) {
        $this->repository = $repository;
        $this->loggerService = $loggerService;
    }

    public function getById($id) {
        $this->loggerService->logText("$id requested");
        $object = $this->repository->getById($id);

        return $object;
    }

}

Also note it still fulfills the UserRepositoryInterface interface, so can be passed to the UserService no problem. The UserService just sees a UserRepository. It doesn't care what other things it does... it just knows it can use it to call getById() and get a user back.

And so on to implement a CachedUserRepository:

class CachedUserRepository implements UserRepositoryInterface {

    private $repository;
    private $cacheService;

    public function __construct(UserRepositoryInterface $repository, CacheServiceInterface $cacheService) {
        $this->repository = $repository;
        $this->cacheService = $cacheService;
    }

    public function getById($id) {
        if ($this->cacheService->isCached($id)) {
            return $this->cacheService->get($id);
        }
        $object = $this->repository->getById($id);

        $this->cacheService->put($id, $object);
        return $object;
    }

}

This one knows about caching, and knows how to call the repo its decorating to do the actual "repo-ing". Again it implements the appropriate interface. Also note that we can pass this constructor a LoggedUserRepository (which itself is passed a UserRepository), and we end up with a repository which handles caching, logging, and... erm... I need a better word... repo-ing. But now all the concerns are nicely separated.

Obviously this takes a bit of wiring up, however it's very easy with a DI container. Here's the relevant bits:

$app["service.user"] = $app->share(function($app) {
    return new UserService($app["repository.user"]);
});

That's it, as far as the UserService goes: give it a UserRepository. Or definition for $app["repository.user"] could just be a UserRepository:

$app["repository.user"] = $app->share(function($app) {
    return new UserRepository($app["datasource.user"]);
});

Or it could do logging:

$app["repository.loggedUser"] = $app->share(function($app) {
    return new LoggedUserRepository($app["repository.user"], $app["service.logger"]);
});

Or a cached one:

$app["repository.cachedUser"] = $app->share(function($app) {
    return new CachedUserRepository($app["repository.user"], $app["service.cache"]);
});

Or they could be wired up another way, to do caching and logging; or logging and caching.

It's just a matter of init-ing the UserService with a different repo:

$app["service.user"] = $app->share(function($app) {
    return new UserService($app["repository.cachedUser"]);
});

Or, hey, another requirement might come along at some point... dunno what it might me... an audit process separate to the logging process or something. Then it's just a matter of creating a new AuditedUserRepository, and all it has to do is audit stuff, then use its dependent UserRepositoryInterface object to do the actual repository stuff (via a logging and caching tier, completely unbeknownst to it).

It also goes without saying (hopefully) that the testing of all this can be far more focused. Testing of each component is completely discrete from the the other components, and they don't need to worry about one another. They're irrelevant. It keeps the code simple and focused, and on-point.

My take-away from this is that if I start piling code or more dependencies into an existing class, I need to stop and think about whether that code is actually anything to do with what the name of the class suggests it should be busying itself with, and if not... I'm perhaps putting the code in the wrong place.

Righto.

--
Adam

Dependency injection strategy discussion

G'day:
Our dev department is spread across two campuses: at our head office in Dublin, and the one I'm based at in London.

Yesterday (Friday) the London bods had our weekly Dev Team catch-up, to discuss various issues that cropped up during the week which need more concerted discussion than an "ad hoc make a decision and get on with it" situation might resolve.

One of the chief discussion points is our dependency injection strategy, and the question was raised if we're doing it right, as it seems there were a few code smells creeping in in places.

As coincidence would have it... when we got out of the meeting a few of us had an email in our inbox from one of our mates in Dublin who was amidst much the same dilemma in some code he was working on.

This resulted in a further discussion between the London people, rounding out the afternoon. I think we clarified a few things really well, re-formalised our DI strategy in our heads, and identified some code we need to look at to work out what the actual cause of the smell is. What was really good is at the end of it we all agreed with where we got to, and the direction to take. As we have a few people who like holding fair strong opinions in the team ([raises his hand gingerly]), this is encouraging.

The gist of the conversation is worth repeating I reckon, and I hope the relevant parties don't mind. And I reckon it shows our team in pretty good light so I reckon the bosses won't mind either. I'm sure I'll find out if not!

OK, so - as you probably know - we're a PHP shop. For the main project I work on (www.hostelbookers.com) - we have just finished retiring the old ColdFusion-based site ("The end of ColdFusion"), replacing it with a PHP one running on the Silex micro-framework. Silex is built around Pimple, Sensio's DI Container. I've written a bit about Silex and Pimple if you want to get the gist of it.

Very quickly, Pimple implements DI via the notion of service providers, one of which might look like this (this is sample code from an earlier blog article: it's not code from our own app, nor is any code in this article):

namespace \dac\silexdemo\providers;

class ServiceProvider implements ServiceProviderInterface {

    use Silex\ServiceProviderInterface;
    use Silex\Application;
    use \dac\silexdemo\beans;

    public function register(Application $app){
        $app["services.user"] = $app->share(function($app) {
            return new services\User($app["factories.user"], $app["services.guzzle.client"]);
        });        

        $app["services.guzzle.client"] = function() {
            return new Client();
        };
    }
    
    public function boot(Application $app){
        // no booting requirements
    }
}

There's a register() method within which one defines all the objects and their dependencies, and a boot() method for calling code on a a defined object to be run before it's used. As all of these are defined using closures, no objects are actually created until they need to be used. Cool.

In this example I'm defining some services, but we define everything via service providers: services, controllers, repositories, factories, helpers etc.

We're defining the user service object there, and you can see from that that its constructor expects a coupla dependencies:

function __construct($userFactory, $guzzleClient){
    $this->userFactory = $userFactory;
    $this->guzzleClient = $guzzleClient;
}

From there, all the code in UserService can use the dependency to help out with its logic. Fairly standard stuff.

The chief conceit here is that we definitely use configuration over convention, and we configure our objects explicitly with the dependencies they need. UserService needs a UserFactory and it needs a GuzzleClient, so we specifically pass those in.

Aside: a word on configuration over convention

I really dislike the "convention" approach to pretty much anything like this... DI config... routing config etc. The reason being that the framework should simply busy itself with frameworking stuff, it should not be dictating to me how I write my code. That is not the job of the framework (be it a DI one or an MVC one). Also conventions are very opinionated, and we all know what is said about opinions. Frameworks that implement convention over configuration position the code as if the framework is the central element to the application, wherein it really ought to simply be some code that sits off to one side, and just gets on with it. My application is what is central to the application.

People will claim that it's easier to use convention of configuration, but I don't believe "easier" should be a primary consideration when designing one's app. Especially when it's "easier to use the framework", rather than "intrinsically good design".

But I digress.

This is fine, and there's no alarm bells ringing there.

Well one slight alarm might that say the object we're defining might have some actual OO type properties. This is a really contrived example (not to mention wrong) example, but this illustrates it: