Skip to content

PHP Proxy Logger Component - Put Back Some Freedom And Silence In You Logs

So what is this component all about?
Basically it is a self developed "Proxy Logger" for php. Furthermore, this projects extends the proxy logger with an buffer and again with a trigger to flush or clean this buffer.

What does a "Proxy Logger" for php mean? It means a proxy for all loggers which implements the "PSR-3 Logger Interface". The proxy forwards all log requests to all attached loggers.
By using the provided "Buffer Logger", you are able to manipulate the forwarding of the log requests to all attached loggers.
Additionally, you can manipulate the buffering itself by using the available "Buffer Manipulators". This enables the possibility to set a trigger for log level to regulate the forwarding of all log requests to all attached loggers.

By the time of this writing, the component is shipped with two manipulators, the "BypassBuffer" and the "FlushBufferTrigger".
You can use the "Bypass Buffer" to regulate which log level bypasses the buffer and are forwarded directly to all attached loggers. The "Flush Buffer Trigger" enables the way to mark a log level as trigger. If this log level is triggerd, the buffer will be flushed which means that all buffered log requests are forwarded to all attached loggers.

After writing about all the fundamental knowledge, lets move on to the "Upward Flush Buffer". The upward flush buffer extends the idea of a triggerd buffer flush by the concept of triggering this flush also if a log level of a higher priority is called. To keep it short, you can define "if at least this log level is called, flush the buffer".

The whole component is shipped with a log of examples.
Since the upward flush buffer trigger is the crown jewel of the component, i want to quote the output of the upward flush buffer trigger versus normal logger example.


----------------------------------------
First run with normal logger without log level restriction.
----------------------------------------
[1381003509] [debug] [processing id 1]
[1381003509] [info] [collection information and data id: 1]
[1381003509] [debug] [done]
[1381003509] [debug] [processing id 3]
[1381003509] [info] [collection information and data id: 3]
[1381003509] [info] [data can not handled with this process, queueing data to manual processing list]
[1381003509] [debug] [done]
[1381003509] [debug] [processing id 8]
[1381003509] [info] [collection information and data id: 8]
[1381003509] [info] [logical problem in data on key 3]
[1381003509] [notice] [trying to recalculate data]
[1381003509] [info] [setting data value of key 7 to default]
[1381003509] [debug] [finished]
[1381003509] [debug] [processing id 4]
[1381003509] [info] [collection information and data id: 4]
[1381003509] [debug] [done]
[1381003509] [debug] [processing id 5]
[1381003509] [info] [collection information and data id: 5]
[1381003509] [info] [logical problem in data on key 6]
[1381003509] [notice] [trying to recalculate data]
[1381003509] [warning] [setting data value of key 7 to default not possible]
[1381003509] [notice] [trying to revert modification]
[1381003509] [error] [runtime data and data in storage differs, can not revert modification]
[1381003509] [critical] [lost connection to storage]
[1381003509] [alert] [can not unlock and schedule processing to id 5]
[1381003509] [debug] [done]
[1381003509] [debug] [processing id 6]
[1381003509] [critical] [lost connection to storage]
[1381003509] [alert] [can not unlock and schedule processing to id 6]
[1381003509] [debug] [done]
----------------------------------------
Second run with normal logger and log level restriction to warning and above.
----------------------------------------
[1381003509] [warning] [setting data value of key 7 to default not possible]
[1381003509] [error] [runtime data and data in storage differs, can not revert modification]
[1381003509] [critical] [lost connection to storage]
[1381003509] [alert] [can not unlock and schedule processing to id 5]
[1381003509] [critical] [lost connection to storage]
[1381003509] [alert] [can not unlock and schedule processing to id 6]
----------------------------------------
Third run with manipulate buffer logger.
----------------------------------------
[1381003509] [debug] [processing id 5]
[1381003509] [info] [collection information and data id: 5]
[1381003509] [info] [logical problem in data on key 6]
[1381003509] [notice] [trying to recalculate data]
[1381003509] [warning] [setting data value of key 7 to default not possible]
[1381003509] [notice] [trying to revert modification]
[1381003509] [error] [runtime data and data in storage differs, can not revert modification]
[1381003509] [critical] [lost connection to storage]
[1381003509] [alert] [can not unlock and schedule processing to id 5]
[1381003509] [debug] [processing id 6]
[1381003509] [critical] [lost connection to storage]
[1381003509] [alert] [can not unlock and schedule processing to id 6]

What does this example show you?
The example shows typical log entries generated by a process that is dealing with a bunch of data.
"First run" is the regular massiv number of entries you have to deal with when you are running you logger without restrictions.
As you can see, it takes some time to figure out if something important happens. Even to find the place where something important happens is hard to find. The "second run" is an example when you run you logger in the restriction of "only log level of warning or above".
First of all, you notice that no debug or info messages are logged. But what is bad about that? You either miss important informations (like the process or data id) or you have to flood your logs with all informations for each log request.
Finally, the "third run" shows what i mean when i am writing about "putting back freedom and silence in your log files". The logger only logs when a critical log level is reached and provides all available informations. If nothing bad happens, nothing will be logged. Quite nice, isn't it?
If a part of the data is processed, the buffer is cleaned when nothing happens. If an important log level is triggerd, the buffer is flushed and all collected log requests are forwarded to all attached loggers.

If you find bugs, bad namings, ugly code, have ideas to improve this component, pull your code or became a participant :-).

FrOSCon - Test Proxies: How Problems Became Features

By Sebastian Bergman and Arne Blankerts.
Keep your eyes up and stay tuned for "patch coverage".
Second time, thanks for the book - handed over by sebastian himself. Mister HowTrueIsFalse, you will get back your book soon :-).

What Is The Talk About

Integration tests closing the gap between unit tests and system tests. This is resolved by keep the focus on interfaces between components and testing that the interaction between the components is working as expected.

Arne Blankerts and Sebastian Bergman showing how a problem by setting up the integration tests became a feature aka "Test Proxies" for PHPUnit.

They also discuss problems and provide solutions for implementing mock objects in php unit and how to ship them as features.

How To Visualize

How lower you go, the faster and the exact the tested code behaves. How higher you go, the more you can provide a stable and general testcase.

  • business
  • technology

  • ui

  • service
  • unit

Isolation, speed (top down) vs Confidence in whole system (bottom up) from how google tests software * large * medium * small

Terms

Test one unit is a unit test.

Write a test between two units is more a integration test than a unit test. Current idea is to stub or mock one of the two units and see how other unit acts.

Push the idea of stubbing and mocking more to the edge will lead to "edge to edge test" like "client to server test". In general, try to test components on the same level (layer).
Try to monitor systems for load tests and use appdynamcis or xdebug and xhprof.

Example

<?php
namespace Company\Project

class SampleWorkflow
{
    private $backend;
    private $service;

    public function __construct(Backend $backend, Service $service)
    {
        $this->backend = $backend;
        $this->service = $service;
    }

    public function execute(Request $request)
        $this->service->workflow(
            $this->backend->getObjectById($request->getValue('id));
        );
    }
}

How to test this?

Would be cool if we can log that code was executed like test proxies by adding an extra flag to the mock builder.
Provides way to see where dataflow changed or drifts from expected way (will be in PHPUnit 3.8).

<?php
namespace Company\Project

use PHPUnit_Framework_TestCase;

class SampleWorkflowTest extends PHPUnit_Framework_TestCase
{
    public function testServiceCallUpdatesObjects()
    {
        $service = $this->getMockBuilder('Service')
            ->enableProxyingToOriginalMethods()
            ->getMock();

        $service->expects($this->once())
            ->method('doWork');

        $backend = new Backend();
        $workflow = new SampleWorkflow($backend, $service);

        $workflow->execute(new Request(array('id' => 42)));
    }
}

tool php classmap generator packagist

After a month, i've finished a tool to create a classmap from a php project. The current stable version is v1.4 and can be found on github.com as well as on packagist.org. Why? Well, obviously because i can (and wanted to learn a few things like tokens, or symfony console) ;-). But for real, when you have to deal with legacy projects or code but want to remove the strange and slow existing autoloader (with all its exception), the easiest way to do this is by using a classmap. I also tried to find a classmap generator that can deal with psr-0 and not psr-0 files, all i could find are generators that support psr-0 files. A classmap itself is just a php array. The key is the full qualified classname and the value is the relative path to the file. Creating a classmap on your own is suitable when you have to manage a number of files below 20. But when it comes to more you can not effort the time to maintain that file. So for a lot of files that are not covert by composer, the classmap generator should be well suitable. It is planned to implement a "phar" classmap generation for the upcoming version. When you want to create phar files, this could be a timesaver as well. The classmap generator is build by using symfony\console and yes, it is a joy to work with that component! Shame on me, the current version is not covered by unittests. After i implemented the current features from the todo list, this will be my major task.

The classmap generator can handle all kind of php files like: - Interface - Abstract Class - Class The generator can handle files with or without namespace. Even files with multiple definitions (interface, abstract class and class in one file) is no problem. Furthermore, you can create multiple configuration files and update this classmaps when needed. Like well known from the composer, the classmap generator is able to create a autoloader file for you. The created autoloader will use the created classmap file and supports psr-0 autoloading. source/link to the wiki

What is left to write? Of course i'm proud about this. What you see right now is the work of one month and after i finished the core design, i rebuild a lot by replacing my cli application class with the symfony\console component. I hope you can use the tool. If you need help or found a bug, contact me on github.com