You should really be using monolog.

If you’ve ever had any problem with a program in your career (hardly ever happens), you’ve checked a log file to help discern “What the !@#$ is happening?”. As PHP professionals we know we should be logging to make systems easier to monitor and debug both for ourselves and anyone else who may inherit them. However, the difficulty of creating poignant, searchable, interpretable logs is often overlooked when accomplishing a new task. So being the professionals we are, we set up a log file, have our application spew to it in a few choice locations, pat ourselves on the back for a job well done, and never look at the log file again.

6 months later something breaks, and we’re no closer to answering the question — “What the !@#$ is happening?”

Monolog is a composer installable package which provides an extensible framework for delivering logs to wherever you would like them, as well as increasing their utility. While it is possible to make that unorganized log file you’re about to make using monolog, it’s much less likely that you will because the framework provides you with the tools, the rules, and the flexibility to do much more.

You should really be using monolog and here’s why.

PSR-3

The php-fig (Framework Interop Group) exists to solve common PHP programming problems. The PSR-3 spec defines a common interface and some helper classes for use by logging libraries. The MonologLogger class is an instance of the PSR-3 LoggerInterface and complies fully with this standard. Yay standards, let’s play nice!

PSR-3 defines eight log levels for defining the priority and intent behind your logs. At a quick glance you can scan for high priority events to get a feel for the health of your system. Using log analyzer tools you can organize, filter, search and visualize your logs based on these event levels in order to quantify and measure system health.

  1. Debug – Detailed debug information. This level is generally for minutia. Often this information is useful during development or bug hunting.

  2. Info – Interesting events. High frequency logs of events which you want to track, possibly store, but are reflective of normal operation of common system tasks. Example: user updates.

  3. Notice – Normal but significant events. These events are excellent for getting a view of the behavior of your system. It’s useful to use notices to mark the kick off, and completion of tasks. Example: Database migration completed OR user unsubscribe from newsletter.

  4. Warning – Exceptional occurrences that are not errors. Anything that interrupts normal operation but isn’t necessarily incorrect. Things in this category can range from use of a deprecated API methods to mindful ignorance of a task which is usually performed but doesn’t break anything when not performed. Example: Disk space is over 80% utilized.

  5. Error – Runtime errors that do not require immediate action but should typically be logged and monitored. These are errors you anticipated and planned to catch. Example: Missing configuration file.

  6. Critical – Critical conditions. This is something your system can recover from, but may necessitate human intervention. These are events you would like to investigate promptly when they arise. Example: Application component unavailable.

  7. Alert – Action must be taken immediately. Major components of the system are broken or completely unavailable. Example: Database unavailable / Web Server down.

  8. Emergency – System is unusable. This is reserved for your applications equivalent of the apocalypse. Something might literally be on fire.

Channel – Broad identification for a log.

When making a Logger you provide a text string which will accompany all logs made by that instance. If you have built a program which does migration for your blog database, you may give it a channel of “blog-migration.” This will help you sort and search your logs by that channel when the time comes.

$logger = new MonologLogger("blog-migration");

Context – Dig into the details.

The logger methods take a message argument to describe the event, as well as an array of “context” data to describe the circumstances of the event. Above all else, the use of context should be to increase log clarity. For example, when you’re logging about saving a user, put the user’s data into context so you know which user the log pertains to.

In general, make your messages broad, and your contexts specific.

Instead of:

$user = new User("username");
$db->put($user);
$logger->info('User ' . $user->username . ' saved.');

Tend toward:

$user = new User("username");
$db->put($user);

$context = get_object_vars($user);
$logger->info("User saved.", $context);

Keeping specifics out of your messages leaves you with consistent homogenous messages you can use when searching. You may want to know how many users are saved in a day, so you do a search for all messages in the last day equal to “User saved.” Now, if you’re interested in seeing a “User saved.” log pertaining to a specific user you can still do that by adding context["username"] === 'bob' to the search conditions.

Using contexts is an easy way to increase the expressiveness of your logs, do it.

Records – Structure of a log.

Records are an associative array which act as the data currency of monolog. In a record you find all the pertinent information which define a log — the level, the message, the context, etc. Here is the basic skeleton of a monolog record:

$record = array(
    'message' => string,
    'context' => array
    'level' => integer,
    'level_name' => string,
    'channel' => string,
    'datetime' => float (unix microtime)
    'extra' => array
);

Handlers – Log here, there, and everywhere.

Monolog handlers allow your logs to be output to multiple destinations. Perhaps you want logs output to the console so you can see them while you’re using a command line tool, but you also want to store them in a .log file, email them to yourself, and store everything in a third party log analysis tool. You can do that with monolog by simply pushing additional handlers. Monolog is shipped with A TON of built in handlers. One of the most common is StreamHandler which logs to an open stream such as php://stdout or a file. There are also built in email handlers for common email libraries, and even some common log storage services like Loggly.

$stdOutHandler = new StreamHandler('php://stdout');
$logFileHandler = new StreamHandler('/path/to/my/logfile.log');

$logglyFormatter = new LogglyFormatter();
$logglyHandler = new LogglyHandler("my-loggly-api-token");
$logglyHandler->setFormatter($logglyFormatter);

$logger = new Logger("blog-migration");
$logger->pushHandler($stdOutHandler);
$logger->pushHandler($logFileHandler);
$logger->pushHandler($logglyHandler);

The loggly handler takes data in a specific format, which is why it has a formatter. Something we haven’t covered, but we will.

At this point you know enough to go start injecting the logger into your classes. You could leave now if you’re saturated with new knowledge and just want to get to it. The next few sections are here if you want to do something custom with Monolog, are just curious, or if you want to provide variability in your setup.

Formatters – Have it your way.

Formatters are exactly what they sound like, they’re for controlling the format of a log record. Monolog supplies several built in formatters, JsonFormatter, HtmlFormatter, ElasticaFormatter, and LogglyFormatter are all examples of formatters provided by the library. These classes implement the FormatterInterface which provides format(array $record) and formatBatch(array $records) methods for altering records.

The JsonFormatter::format() method for instance is quite a simple example which conveys the general idea.

public function format(array $record)
{
    return json_encode($record) . ($this->appendNewline ? "n" : '');
}

It receives a record, and returns its json encoded value.

Processors – Do something, do more.

We learned above that contexts are a good way to store extra data in a log record. Processors are an alternative way to store “extra” data in a log record. Processors are PHP callables with an __invoke magic method that takes the record as it’s first argument, alters the extra key of the record, and returns it when it’s done processing. A processor allows you to do something, to run some addtional code at log time and stick the results into the record.

Processors can be pushed onto the Logger instance itself to process all records, or to individual handlers to process only the records sent to that handler. The logger and handlers then execute all the processors while they’re building log records.

Monolog being pretty awesome, has of course provided several built in processors which make excellent examples of what you can do with a processor. The ProcessIdProcessor for instance adds the current PHP process id to the record.

class ProcessIdProcessor
{
    /**
     * @param  array $record
     * @return array
     */
    public function __invoke(array $record)
    {
        $record['extra']['process_id'] = getmypid();

        return $record;
    }
}

Verbosity Levels – Take only what you want.

public function __construct($level = Logger::DEBUG, $bubble = true);

Above is the signature of monolog’s AbstractHandler base class. This means that all handlers built from that base class (most, if not all of them) take a $level argument which sets the minimum log level for that handler. This is really useful, because as you start using your logs more often you will quickly discover that most of the time you do not care about every single minute detail, and it is nice to turn down the volume. At Cascade Energy we have a file import process which ingests data into our system, we’ve set the LogglyHandler in that system to a level of Logger::NOTICE, because with anymore verbosity than that it becomes difficult to get a feel for what is happening. Unless you are a masochist you probably don’t want an email every time a user is saved, you might want to set the level to Logger::CRITICAL so you only get emails when you log a critical, alert, or emergency.

Thanks for reading

The goal here was to give a quick synopsis of some of the things monolog can help you do to organize and solidify the way you log in PHP applications, I hope if you were confused about monolog you have a clearer picture, and if you were on the fence about using monolog, I hope I’ve pushed you over. I’m using this framework often, so feel free to ask me questions on twitter @nackjicholsonn. If I can, I will answer them.

composer require monolog, you should really be using it.

Read more "You should really be using monolog."

How I let TDD happen in PHP

Test Driven Development is a practiced skill. I’ll be the first to tell you, I don’t have it. I am working on it though. What I want to share in this blog is the process I go through to flip my brain from thinking about how to write code, to thinking about how to write tests I can code against.

I’m going to assume if you’ve found this blog you already know what TDD is, why you should be doing it, the basics of PHPUnit, and you don’t need a lengthy description of what we’re talking about here. The gist is this:

#!txt
1. Write unit tests
2. Write code that passes those tests.
3. Refactor without failing the tests.

The Task

Before you start you should know what you want to do. Writing tests first will force you to make a plan. In the case of the example for this blog — I had data coming back from a message queue service in the form of an associative array, and I wanted to put the message information into a Data Transfer Object (DTO). You can think of a DTO as a bag of data as a class. In php having data structured in a class means you can leverage type hinting and checking to do more with it than you can with an associative array. That’s more than I’ll go into now, but just know, I had like totally really important reasons to do this job:

#!php
[
    'body' => '{"foobar": "JSON message!"}',
    'receiptHandle' => 'abc123',
    // ...
    // And many other properties I don't need
]

INTO

#!php
class Message
{
    public $body = '{"foobar": "JSON message!"}';
    public $receiptHandle = 'abc123';
}

I’m going to call my thing that does this job a MessageHydrator, because…someone came up with that name. It’s a thing in OO design. If you need a metaphor, I got you! Data is water and class rhymes with glass, and if you put data in a class it is hydrated.

So I need a test which will prove that my MessageHydrator class can take an associative array and turn it into a Message.

#!php
namespace CascadeSenseiDataMessage;



class MessageHydratorTest extends PHPUnit_Framework_TestCase
{
    /** @var MessageHydrator */
    private $hydrator;

    public function setUp()
    {
        $this->hydrator = new MessageHydrator();
    }

    public function testItShouldHydrateAMessageFromSourceData()
    {
        $message = new Message();
        $sourceData = ['body' => 'foo', 'receiptHandle' => 'bar'];

        $this->hydrator->hydrate($sourceData, $message);

        $expectedMessage = new Message();
        $expectedMessage->body = 'foo';
        $expectedMessage->receiptHandle = 'bar';

        $this->assertEquals($expectedMessage, $message);
    }
}

Okay, that fails. I need to write a class that passes it. Minimally! Don’t get all fancy and do the correct things you know you need to do, just pass the test.

I’m going to take keys and put them on a Message. That’s it!

#!php
namespace CascadeSenseiDataMessage;


class MessageHydrator
{
    public function hydrate($sourceData, Message $message)
    {
        $message->body = $sourceData['body'];
        $message->receiptHandle = $sourceData['receiptHandle'];
    }
}

Bingo!

Green. But, that can’t be enough right? Now I stop and think about things for a second. This doesn’t really meet the requirements of my plan — remember all that data I need to ignore? I should make sure that works.

#!php
public function testItShouldHydrateAMessageFromSourceData()
{
    $message = new Message();

    $sourceData = [
        'body' => 'foo',
        'receiptHandle' => 'bar',
        // Just gonna add one more thing here
        'doNotWant' => 'noThanks'
    ];

    $this->hydrator->hydrate($sourceData, $message);

    $expectedMessage = new Message();
    $expectedMessage->body = 'foo';
    $expectedMessage->receiptHandle = 'bar';

    $this->assertEquals($expectedMessage, $message);
}

Oh cool, tests are still green. I’m done, this code is perfect.

And honestly I could be done, this code works. But there is that step 3, the pesky refactoring part. Now is the time for reflection, and deep honesty with yourself about how bad you are at this. Ask could this be better?

Yes.

It would be nice if I didn’t hardcode every single property translation. With a small list like this it’s not a big deal, but let’s say a week from now (and every week after that) it becomes necessary to add some other data attribute out of the associative array, what do I do then? This is software folks, change is going to happen. I add a property Message::property, and another line of code in the hydrator $message->property = $sourceData['property'];. Pretty soon I have a maintenance headache in the hydrator class. It would be nice if I just added my properties to the Message class, and the hydrator could just know that if the property is in the class, I should take it out of the array and put it there. This is a job for a loop!

Let’s refactor:

#!php
class MessageHydrator
{
    public function hydrate($sourceData, Message $message)
    {
        foreach ($sourceData as $property => $value) {
            $message->$property = $value;
        }
    }
}

Oh god, that fails. Abort the mission! No…maintainability is worth it.

At this point the test will output this: Failed asserting that two objects are equal.

Okay, to really see why those objects aren’t equal I step through debug the code on the line which is failing and I find that the Message has a property Message::doNotWant equal to noThanks. Oops, we need to skip properties that aren’t defined in the Message class. PHP has a function property_exists we can use to check, and just continue to the next property.

#!php
class MessageHydrator
{
    public function hydrate($sourceData, Message $message)
    {
        foreach ($sourceData as $property => $value) {
            if (!property_exists($message, $property)) {
                continue;
            }

            $message->$property = $value;
        }
    }
}

Bango!

Tests are green.

But the famed Portland Trailblazers radio announcer Bill Schonley had a catchphrase “Bingo! Bango! Bongo!”. I don’t know what it meant, but it sounded great on the radio. We only have “Bingo! Bango!” and it just doesn’t have that same ring.

I just want to test a few more things.

What if I under load the array by omitting the body key? I should get a message that has a receipt, but body is null. Write the test.

#!php
public function testItShouldIgnorePropertiesAbsentFromSourceData()
{
    // Intentionally leaving out the body.
    $sourceData = ['receiptHandle' => 'bar'];

    $expectedMessage = new Message();
    $expectedMessage->receiptHandle = 'bar';

    $message = new Message();
    $this->hydrator->hydrate($sourceData, $message);

    $this->assertEquals($expectedMessage, $message);
    $this->assertNull($message->body);
}

What if $sourceData wasn’t an array at all! What if it were a stdClass with properties. It could happen, and I think this code would work for it.

#!php
public function testItShouldHydrateDtoFromObject()
{
    $sourceData = new stdClass();
    $sourceData->body = 'foo';
    $sourceData->receiptHandle = 'bar';
    $sourceData->doNotWant = 'NoThanks';

    $expectedMessage = new Message();
    $expectedMessage->body = 'foo';
    $expectedMessage->receiptHandle = 'bar';

    $message = new Message();
    $this->hydrator->hydrate($sourceData, $message);

    $this->assertEquals($expectedMessage, $message);
}

Bongo!

The tests still pass. This code is done.

Thanks so much for reading. Hope it helps. If you have comments, leave em. If you want to see if I can write shorter things follow me on twitter @nackjicholsonn

Read more "How I let TDD happen in PHP"

Mocking $resource and promises in AngularJS unit tests.

Test setup is hard, it’s tricky, and it feels like a hack. That’s how you know you’re doing it right. (maybe?)

This Post Aims to Cover

  • Why you aid testability by wrapping $resource in an api service.
  • Test setup and mocking in jasmine to handle api services.
  • How to test and resolve promises in your controller specs.

All of the code is available on plunkr

Wrap $resource in a service.

Dependency injection and single responsibility principle are crucial to testability. When you instantiate and create a $resource object in your controllers you are being detrimental to the testability of that controller because you can no longer separate the two. Isolate the functionality of your controllers away from the grunt work of the services they use. The intent of controllers is to glue data models and ui methods to the $scope. It’s so easy with angular to do everything in your controllers, but you need to resist that urge and try to recognize when you have the opportunity to refactor a dependency injectable service into your design.

Instantiation and Tight Coupling:

angular
    .module('BreakfastApp')
    .controller(
        'BreakfastCtrl',
        function($scope) {
          // ANTI-PATTERN !!!
          var BagelResource = $resource('bagels.json');
        }
     );

Dependency Injection:

angular
    .module('BreakfastApp')
    .controller(
      'BreakfastCtrl',
      function(
        $scope,
        bagelApiService
      ) {
        // bagelApiService is injected.
      }
    );

Test setup and $resource mocking

This is the controller we’re testing:

script.js

// Breakfast App
angular.module('BreakfastApp', ['ngResource']);

// Bagel Api Service
angular.module('BreakfastApp').factory(
  'bagelApiService',
  function($resource) {
    return $resource('bagels.json');
  }
);

// Breakfast Controller
angular.module('BreakfastApp').controller(
  'BreakfastCtrl',
  function($scope, bagelApiService) {
    bagelApiService
      .query()
      .$promise
      .then(function(bagelsResponse) {
        $scope.bagels = bagelsResponse;
        $scope.somethingAfterBagelsLoad = true;
      });
  }
);

This is the entire example application. It consists of one controller which loads a collection of bagels via an “api” call (a flat bagels.json file for the sake of the example). The only other thing it does is set somethingAfterBagelsLoad to true. This is a trivial thing to do after the bagels are loaded, and is again just for the purpose of exemplifying the use of promises and how to test them.

Okay, let’s have a look at them specs.

specs.js

describe('BreakfastCtrl', function() {
    var $q,
        $rootScope,
        $scope,
        mockBagelApiService,
        mockBagelsResponse;

beforeEach(module('BreakfastApp'));

beforeEach(inject(function(_$q_, _$rootScope_) {
  $q = _$q_;
  $rootScope = _$rootScope_;
}));

This loads the $q and $rootScope angular services. The inject method can handle special dependencies wrapped on either side by _ as a convenience. This allows for assigning their values to local variables named appropriately.

I need $q in order to build a promise I can return from the bagelApiService. I need $rootScope to both make a new scope for the BreakfastCtrl and to propagate promise resolutions. $q is integrated with $rootScope, read about it in the $q documentation.

beforeEach(inject(function($controller) {
  $scope = $rootScope.$new();

  mockBagelApiService = {
    query: function() {
      queryDeferred = $q.defer();
      return {$promise: queryDeferred.promise};
    }
  }

  spyOn(mockBagelApiService, 'query').andCallThrough();

  $controller('BreakfastCtrl', {
    '$scope': $scope,
    'bagelApiService': mockBagelApiService
  });
}));

This block builds the dependencies for the controller, and constructs it via the $controller service. This alters the controller’s understanding of what $scope and bagelApiService are, and replaces them with objects made locally. If you’re not familiar with unit testing, or its purpose, this can be a confusing thing to do. Why are we doing this? Why make fake objects to trick the controller? The answer is pretty simple: to isolate the subject of the test and write reliable assertions.

For instance, the mockBagelsResponse we made at the top of the file is a set of predictable values used in the tests below to make assertions. With the mock for the bagelApiService in place, those predictable values will be used to resolve the queryDeferred.promise used by mockBagelApiService.query without ever actually running any code from the real bagelApiService or sending any real requests to the “api”.

Test and resolve promises in the controller specs

describe('bagelApiService.query', function() {

    beforeEach(function() {
      queryDeferred.resolve(mockBagelsResponse);
      $rootScope.$apply();
    });`

Resolve the bagelApiService.query method’s promise with a fake, but predictable mockBagelResponse array. Propagate the resolution with $rootScope.$apply().

  it('should query the bagelApiService', function() {
    expect(mockBagelApiService.query).toHaveBeenCalled();
  });

  it('should set the response from the bagelApiServiceQuery to $scope.bagels', function() {
    expect($scope.bagels).toEqual(mockBagelsResponse);
  });

  it('should set $scope.somethingAfterBagelsLoad to true', function() {
    expect($scope.somethingAfterBagelsLoad).toBe(true);
  });
});

Those tests end up pretty simple, which is what you want. The service was called, the $scope.bagels are set, and $scope.somethingAfterBagelsLoad happened.

Thanks for reading

I sincerely hope this helps you figure out how to test your angular code. The usefulness of promises comes up a lot, and there aren’t enough in depth examples of how to write angular with $q and even fewer examples of how to test it. At Cascade Energy, much of our client code utilizes the promise api, and as a result I have a fairly large amount of experience working with and testing it. Please feel free to reach out with questions here on the blog or on twitter @nackjicholsonn if you have concerns that go beyond the bounds of this simplified example. Cheers, thanks for reading.

Again, run, fork, and play with this plunkr

Read more "Mocking $resource and promises in AngularJS unit tests."