Apache combined log format with Traffic Server


If you’re using apache traffic server, all of your traffic is going through your proxy, not your web server.  This is a problem if you rely on your logs for visitor data.

You can get traffic server to output logs in apache’s combined log format, though.  Then you just feed traffic server’s logs to your log analysis app.

Here’s how to do it:

Edit /usr/local/etc/trafficserver/logs_xml.config

Add these lines to the bottom:

<LogFormat>
    <Format = "%<chi> - - [%<cqtn>] \"%<cqhm> %<cquup>\" %<pssc> %<psql> \"%<{Referer}cqh>\" \"%<{User-Agent}cqh>\"" />
    <Name = "httpd_combined"/>
</LogFormat>
<LogObject>
    <Format = "httpd_combined"/>
    <Filename = "access"/>
</LogObject>

Edit /usr/local/etc/trafficserver/logs_records.config

Change

CONFIG proxy.config.log.custom_logs_enabled INT 0

to

CONFIG proxy.config.log.custom_logs_enabled INT 1

Then restart traffic server

trafficserver restart

Now you’ll have an apache combined log file in /usr/local/var/log/trafficserver/access.log

You can read more about apache traffic server’s logging options here and the log formats here.

Advertisements

Use register_tick_function to profile your code


Okay, so your code is slow.  Why?  Is it your webservice call?  Or a new plugin you installed?  Is it your database calls?  File I/O?  You need a profiler.  A profiler gives you the ability to trace the performance of your code through every function call and create an overview of your system’s performance over a certain time period and helps you make intelligent decisions about where to look for problems.

Code profilers like xdebug and xhprof are essential tools to have for diagnosing performance bottlenecks.  I highly recommend you check them out.  If you have access to installing these extensions on your system, you can probably stop reading here.

But what if you’re in an environment where you can’t install an extension? Luckily, php has a built-in function called register_tick_function that gives you a way to hook in to every user function that’s called.  With this, you can write a profiler yourself.

Here’s some sample code to show you what I mean:

declare(ticks=1);
register_tick_function('do_profile');

a();

function do_profile() {
    $bt = debug_backtrace();
    if (count($bt) <= 1) {
         return;
    }
    $frame = $bt[1];
    unset($bt);
    $function = $frame['function'];
    echo __FUNCTION__ . ' :: ' . $function . PHP_EOL;
}

function a() {
    echo __FUNCTION__ . PHP_EOL;
    b();
}

function b() {
    echo __FUNCTION__ . PHP_EOL;
    c();
}

function c() {
    echo __FUNCTION__ . PHP_EOL;
}

And the output:

a
do_profile :: a
b
do_profile :: b
c
do_profile :: c
do_profile :: b
do_profile :: a

You’ll see in the output that the tick function is being called when the function is called, and again when the function is removed from the stack.

This can be incredibly useful if you attach a timer to it.

Note:  the declare(ticks=1); line is mandatory, it tells php to call your tick handler for every function.  You can change this to declare(ticks=10); to call the tick handler every tenth function if that fits your needs.

Here’s a very simple example of a working profiler. It’s practically the same code as above, but with a timer attached and a shutdown handler to show you the profile when the script is done:

declare(ticks=1);
register_tick_function('do_profile');
register_shutdown_function('show_profile');

$profile = array();
$last_time = microtime(true);

a();

function do_profile() {
    global $profile, $last_time;
    $bt = debug_backtrace();
    if (count($bt) <= 1) {
        return ;
    }
    $frame = $bt[1];
    unset($bt);
    $function = $frame['function'];
    if (!isset($profile[$function])) {
        $profile[$function] = array(
            'time'  => 0,
            'calls' => 0
        );
    }
    $profile[$function]['calls']++;
    $profile[$function]['time'] += (microtime(true) - $last_time);
    $last_time = microtime(true);
}

function show_profile() {
    global $profile;
    print_r($profile);
}

function a() {
    usleep(50 * 1000);
    b();
}

function b() {
    usleep(500 * 1000);
    c();
}

function c() {
    usleep(5000 * 1000);
}

And the output hopefully matches what you would expect:

Array
(
    [a] => Array
        (
            [time] => 0.0511748790741
            [calls] => 2
        )

    [b] => Array
        (
            [time] => 0.500598907471
            [calls] => 2
        )

    [c] => Array
        (
            [time] => 5.00052690506
            [calls] => 1
        )

)

The timing matches what we set in each function. The calls, though, is a bit off, since the tick handler can be called twice for each function. Just note that when you’re interpreting the results.

You can really amp this up to get some good info, though.  Check this out:

P3 Profiler Timeline

If you want to see how it’s done, or see how well it works, give the P3 Plugin for WordPress a look.

Caveats

The tick function is a user function.  This means that whenever php calls a user function it will call your tick function first, but since your  tick function is itself a user function, it will also have the tick function called for it.  It stops after one level of recursion.  Be sure to check for that in your code!

Ticks will not be called on php internal functions.  If your app is having problems due to I/O or an extension, you won’t be able to get the same granularity with a tick function as with an extension based profiler.

Bytecode optimizers will cause you problems.  Function calls will happen, but they won’t be sent through the tick function.  Not exactly sure why on this, but here’s what I’ve got so far:

  • eaccelerator – optimization definitely causes problems
    • disable method 1 – set eaccelerator.optimizer to false
    • disable method 2 – if your app is in eaccelerator’s admin path, call eaccelerator_optimizer(false);
  • xcache – the documentation says there is no optimizer until version 2.0, but experimentation shows some missing function calls, no solution yet
  • zend optimizer+ –  some problems – you can turn this off by setting zend_optimizerplus.optimization_level to 0
  • apc – optimization was removed in 3.0.13 – no problems found
  • wincache – no problems found
  • ioncube – no problems found
  • zend guard loader – no problems found

There’s a warning that this function is not compatible with multi-threaded web servers and php < 5.3.  See the documentation on php.net for more details

Remember to optimize the tick function!  It will be called hundreds or thousands of times in your app, so milliseconds will add up!  If you have a slight mistake in your timing here, it will cause a big shift in your results.

How to Unit Test pcntl_fork()


At some point, many php developers turn to the pcntl functions in php to write a daemon, or server, or simulate threading.

But how do you unit test this with complete code coverage?  Here’s the sample code we’ll be testing:

// @codeCoverageIgnoreStart
if (!defined('TEST_MODE')) {
	define('TEST_MODE', false);
}
// @codeCoverageIgnoreEnd
function start_process() {
	$pid = pcntl_fork();
	if (-1 == $pid) {
		die('Error forking');
	} elseif ($pid > 0)  {
		do {
			echo "Parent - " . getmypid() . "\n";
			sleep(1);
		} while (!TEST_MODE);
	} else {
		echo "Child - " . getmypid() . "\n";
		die();
	}
}

We’ll need to overcome a few big challenges in testing this code:

  • PHPUnit will not re-assemble code-coverage results from across different processes.  This test must remain in one process.  (I’ve tried to find a reference for this, but I can’t … PHPUnit is moving towards parallelized tests, but isn’t there yet)
  • Any calls to die() or exit() will end the test prematurely.
  • The call to sleep(1) will take 1 second of wall time in the test.  That can add up quickly if you have lots of test cases.
  • There isn’t a reliable way to make fork() return -1 to test the error handling branch of the code.

We need to engage some black arts php extensions to make this happen.  An installation guide follows, and the post ends with a complete listing of the unit test.

Disclaimer

These extensions are meant for testing.  These are for your dev or test servers.  Please do not install these on your production servers unless you’re really positive that you want to have them available in your production environment!

Test Helpers

First we’ll need the test_helpers.so extension.  This will let you substitute a callback for any calls to die or exit.

This is a zend_extension, it must be loaded in the correct order, so this one may take some trial and error to get working properly with other zend extensions like xdebug and ioncube.  You can find the extension on github:  https://github.com/sebastianbergmann/php-test-helpers

Once you’ve downloaded and unzipped the package and are in the folder, you can install with:

$ pecl install package.xml

Then add this to your php.ini file:

zend_extension=/path/to/your/php/modules/test_helpers.so

And when you type php -m at the command line, you should see “test_helpers” listed as a Zend Module and a PHP Module.

Runkit

Runkit is a really fun extension that lets you rewrite functions at runtime, execute code in a sandbox, run lint checks on files without spawning a separate process, and other tasks that you probably shouldn’t be doing.  I’ve caused many segfaults in php with runkit.  It doesn’t come with too many safety guards, so be careful with it (see the disclaimer about not running this in production).  You can find the latest version on github here:  https://github.com/zenovich/runkit/

Once you’ve downloaded and unzipped the package and are in the folder, you can install with:

$ pecl install package.xml

Then add this to your php.ini file:

extension=runkit.so

And when you type php -m at the command line, you should see “runkit” listed as a PHP Module.  One last thing, make sure to change this configuration setting for runkit so you can change internal php functions:

runkit.internal_override = 1

The Unit Test

I will skip the guided tour of the evolution of this unit test and jump straight to the finished product.  Here’s a full unit test of the forking code above with 100% coverage.

Note: In the original file, there are ignore coverage wrappers around the code that turns off test mode. Usually this flag is not in a conditional block, it’s set by the application’s framework and is based on the environment + configuration file.  To keep things simple, I’ve chosen to demonstrate this method using a constant.

class ForkTest extends PHPUnit_Framework_TestCase {

	/**
	 * Calls to our mock functions
	 * @var array
	 */
	public static $mock_calls = array(
		'sleep'      => 0,
		'pcntl_fork' => 0,
		'_die'       => 0
	);

	/**
	 * Constructor
	 * Check for necessary php extensions
	 */
	public function __construct() {
		if (!extension_loaded('test_helpers')) {
			echo "These unit tests require the test_helpers extension.  For more information, please visit:\n";
			echo "https://github.com/sebastianbergmann/php-test-helpers\n";
			exit(1);
		}
		if (!extension_loaded('runkit')) {
			echo "These unit tests require the runkit extension.  For more information, please visit:\n";
			echo "https://github.com/zenovich/runkit/\n";
			exit(1);
		}
		parent::__construct();
		define('TEST_MODE', true);
	}

	/**
	 * Setup
	 */
    protected function setUp() {

		// Disable exit / die functionality
		set_exit_overload(array(__CLASS__, '_die'));

		// Sleep quicker (seconds -> milliseconds)
		runkit_function_copy('sleep', '__backup_sleep');
		runkit_function_redefine('sleep', '$sec', 'ForkTest::sleep($sec);');

		// Reset mock calls
		foreach ( array_keys(self::$mock_calls) as $key ) {
			self::$mock_calls[$key] = 0;
		}

		// Get the system under test
		require_once('./fork.php');
    }

	/**
	 * Tear down
	 */
	protected function tearDown() {

		// Restore exit/die functionality
		unset_exit_overload();

		// Restore the original sleep() function
		runkit_function_remove('sleep');
		runkit_function_copy('__backup_sleep', 'sleep');
		runkit_function_remove('__backup_sleep');
	}

	/**
	 * Test the parent path of pcntl_fork()
	 */
    public function testParent() {

		// Force pcntl_fork to return 1 (meaning parent)
		runkit_function_copy('pcntl_fork', '__backup_pcntl_fork');
		runkit_function_redefine('pcntl_fork', '', 'return ForkTest::pcntl_fork(1);');

		// Baseline assertions
		$this->assertEquals(self::$mock_calls['sleep'],      0);
		$this->assertEquals(self::$mock_calls['pcntl_fork'], 0);
		$this->assertEquals(self::$mock_calls['_die'],       0);

		// Call forking code
		start_process();

		// Stuff happened
		$this->assertEquals(self::$mock_calls['sleep'],      1);
		$this->assertEquals(self::$mock_calls['pcntl_fork'], 1);
		$this->assertEquals(self::$mock_calls['_die'],       0);

		// Retore original pcntl_fork functionality
		runkit_function_remove('pcntl_fork');
		runkit_function_copy('__backup_pcntl_fork', 'pcntl_fork');
		runkit_function_remove('__backup_pcntl_fork');
    }

	/**
	 * Test the child path of pcntl_fork()
	 */
    public function testChild() {

		// Force pcntl_fork to return 0 (meaning child)
		runkit_function_copy('pcntl_fork', '__backup_pcntl_fork');
		runkit_function_redefine('pcntl_fork', '', 'return ForkTest::pcntl_fork(0);');

		// Baseline assertions
		$this->assertEquals(self::$mock_calls['sleep'],      0);
		$this->assertEquals(self::$mock_calls['pcntl_fork'], 0);
		$this->assertEquals(self::$mock_calls['_die'],       0);

		// Call forking code
		start_process();

		// Stuff happened
		$this->assertEquals(self::$mock_calls['sleep'],      0);
		$this->assertEquals(self::$mock_calls['pcntl_fork'], 1);
		$this->assertEquals(self::$mock_calls['_die'],       1);

		// Retore original pcntl_fork functionality
		runkit_function_remove('pcntl_fork');
		runkit_function_copy('__backup_pcntl_fork', 'pcntl_fork');
		runkit_function_remove('__backup_pcntl_fork');
    }

	/**
	 * Test the error path of pcntl_fork
	 */
    public function testCouldNotFork() {

		// Force pcntl_fork to return -1 (meaning could not fork)
		runkit_function_copy('pcntl_fork', '__backup_pcntl_fork');
		runkit_function_redefine('pcntl_fork', '', 'return ForkTest::pcntl_fork(-1);');

		// Baseline assertions
		$this->assertEquals(self::$mock_calls['sleep'],      0);
		$this->assertEquals(self::$mock_calls['pcntl_fork'], 0);
		$this->assertEquals(self::$mock_calls['_die'],       0);

		// Call forking code
		start_process();

		// Stuff did not happen
		$this->assertEquals(self::$mock_calls['sleep'],      0);
		$this->assertEquals(self::$mock_calls['pcntl_fork'], 1);
		$this->assertEquals(self::$mock_calls['_die'],       1);

		// Retore original pcntl_fork functionality
		runkit_function_remove('pcntl_fork');
		runkit_function_copy('__backup_pcntl_fork', 'pcntl_fork');
		runkit_function_remove('__backup_pcntl_fork');
    }

	/**
	 * Pretend to fork
	 * @param int $return_value
	 * @return int
	 */
	public static function pcntl_fork($return) {
		self::$mock_calls[__FUNCTION__]++;
		return $return;
	}

	/**
	 * Mock sleep function
	 * Sleep a little bit (seconds -> millisecond)
	 * @param int $sec
	 */
	public static function sleep($sec) {
		self::$mock_calls[__FUNCTION__]++;
		usleep($sec * 1000);
	}

	/**
	 * Mock die function
	 * @return bool
	 */
	public static function _die() {
		self::$mock_calls[__FUNCTION__]++;
		return false;
	}
}

And the proof:

[root@server1 forktest]# phpunit --coverage-html=/var/www/html/coverage/ ForkTest.php
PHPUnit 3.6.4 by Sebastian Bergmann.

.Parent - 25260
.Child - 25260
.

Time: 0 seconds, Memory: 5.75Mb

OK (3 tests, 18 assertions)

Generating code coverage report, this may take a moment.
Code Coverage Report

Code Coverage Report

Visual PHP Unit + WordPress Unit Tests


I saw VisualPHPUnit and was immediately interested.  This provided a very nice visual wrapper to PHPUnit without full blown continuous integration, and kept a history of your test passes / fails.

VisualPHPUnit

VisualPHPUnit is a wrapper for PHPUnit.  It expects that your tests are compatible with PHPUnit’s command line test runner already.

Could this work with WordPress’ Unit Tests?  After some investigation, I’m sad to report that, no, it can’t.  VisualPHPUnit makes several assumptions that are incompatible with WordPress’ test suite.  These are not bad assumptions, just incompatible ones.

  • Include the bootstrap before the PHPUnit library.  This causes problems because the bootstrap cannot reference PHPUnit (e.g. extending PHPUnit_Framework_TestCase).
  • Always include the PHPUnit library.  This causes problems because the bootstrap may have already included PHPUnit (to solve the above problem).  Code like this would solve the issue:
    if( !function_exists( 'phpunit_autoload' ) ) {
    require_once( 'PHPUnit/Autoload.php' );
    }
  • Each test case (a class) is assumed to be in a single file, and named accordingly.  WordPress sometimes groups multiple test cases together in a single file.  A good example of this is test_includes_formatting.php.

Why don’t I submit these issues to VisualPHPUnit?  These aren’t bugs.  They are incompatibilities between how VisualPHPUnit expects things to be done, and how WordPress’ Unit Test do things.  Changing these items in VisualPHPUnit could break compatibility with other projects.

Why don’t WordPress’ unit tests conform to PHPUnit’s structure?

WordPress was also released in 2003, which was before test-driven-development really took off in the php world.  Having a testable app requires a certain design.

Also, WordPress wasn’t written from scratch.  WordPress started as a fork of B2/cafelog.  It wasn’t a greenfield design.

Why doesn’t WordPress just fix their unit tests now?

The core dev team wants a more testable app, and they are working to retrofit unit tests into WordPress, but this is a big challenge.

There are situations in WordPress which are difficult to test, but work perfectly fine.  The dev team is left with a difficult choice:  Rewrite a functioning piece of code to be more testable, but possibly introduce new bugs, or leave it alone and put off a new test framework a little longer.

You can actually see some discussion about this on ticket 17749.

WordPress on WAMP


Here’s a quick walk-through on setting up a WordPress dev environment on Windows using WampServer.

Install WampServer

Visit wampserver.com and download the latest version of WampServer.  This package contains Apache2, PHP 5.3, MySQL 5 and phpMyAdmin.

Download the installer for your version of windows.  If you don’t know if your system is 32-bit or 64-bit, right-click on “My Computer” and then click “Properties.”

For Vista and later, look for look for “System Type”

System Type

For Windows XP, look for “x64” in the “System” description.

Windows XP

For this walk-through, I will assume you’ll install WampServer to the default folder of c:\wamp.  The installation process should look like this:

Configure WampServer

After you’ve installed WampServer, you’ll need to start it and set some configuration options.

  1. Test that your installation works by visiting http://localhost/.  If it doesn’t work, you’ll want to check that your hosts file has localhost mapped to 127.0.0.1 and that you’re not running any other services on port 80. Other web servers (IIS, XAMPP) will try to use port 80.  Also WebDAV services (some web drive applications) will try to use port 80.  WampServer will tell you if it’s working by the color if its tray icon.  Green is working, orange is halfway working, and red is not working at all.
    WampServer - Green icon means it's working
  2. Check to see that phpMyAdmin is working by visiting http://localhost/phpmyadmin/.  If you get an error message of  Cannot connect: invalid settings then you’ll need to edit your c:\wamp\apps\phpmyadmin3.3.9\config.inc.php file (your version number may differ) and add this line to your $cfg array (around line 114 or so):
    $cfg['Servers'][$i]['AllowNoPassword'] = TRUE;
  3. Once phpMyAdmin is working, create a database for WordPress (I call mine “wordpress-trunk”), then create a user with privileges on the database.  In a production environment, make sure you do your research on what these privileges mean and grant only the necessary privileges (e.g. your user will never need GRANT and should never need, CREATE VIEW, CREATE ROUTINE, TRIGGER, etc.).  Here’s what the process looks like in phpMyAdmin:
  4. Click on the WampServer icon, go to the php menu, click on the “php.ini” option.  This will open Apache’s php.ini file (note: there’s a separate php.ini file for the CLI version of php located in c:\wamp\bin\php\php5.x.y\php.ini).  Adjust the following settings:
    1. error_reporting = E_ALL ^ E_DEPRECATED
    2. error_log = "c:/wamp/logs/php_error.log"
    3. upload_max_filesize = 50M
    4. post_max_size = 50M
  5. Enable php’s openssl extension by clicking on the WampServer icon, then the php menu, then php extensions menu, then make sure php_openssl is enabled.  If it’s not, click it.  WampServer will enable the module in php.ini and restart apache.
    Enable the openssl extension
  6. When you’ve finished adjusting your settings, click on the WampServer icon, then click on “Restart All Services” to make the changes take effect

Install a Subversion Client

My personal choice of subversion clients is SmartSVN.  My personal taste is to have a separate, self-contained, client and not to use the version control IDE integration and shell integration features that have become popular recently.  SmartSVN offers a free version and a paid version.  Another very popular option is to use  TortoiseSVN.  If you’d like to use the command line, you can find windows packages for that, too.

Install WordPress

The most complete resource for this is the codex.  For the purposes of this walk-through, you’ll want to check out http://core.svn.wordpress.org/trunk/ to a folder under c:\wamp (e.g. c:\wamp\wordpress-trunk).  Then point your browser to http://localhost/wordpress-trunk/ and walk through the installation process.  You should see that WordPress created a wp-config.php file for you and this file shows as new in your local subversion project. Unless you have commit access (you don’t) you cannot commit changes back to the repository.  Any attempt to do so will result in an error.

Now that you have WordPress installed, visiting http://localhost/wordpress-trunk/ should give you the familiar WordPress home page you’re used to, and http://localhost/wordpress-trunk/wp-admin/ should give you the admin page.

Install Some Plugins

Chances are that your outgoing e-mail will not work.  I suggest using the Configure SMTP plugin and using gmail’s SMTP servers.
Configure SMTP Plugin

I also recommend the Debug Bar and Debug-Bar-Extender plugins.  To make the best use of these plugins, edit your wp-config.php file and enable WP_DEBUG and SAVEQUERIES.  Make sure to see the codex for more wp-config development options.

If you want some sample content, I suggest downloading the Theme Unit Test XML file from the Codex and importing it into your site.  You can do this by using navigating to the Tools menu, Import option, then choose WordPress.  You may need to install the WordPress importer plugin.  After that, just upload the XML file, and make sure to check “Download and import file attachments” option so that the images are saved to your local wp-content/uploads folder.

Note:  Jetpack will not work unless your development site is publicly accessible and DNS that resolves correctly.  Generally speaking, don’t use Jetpack on your dev site unless you know what you’re doing.

Install an IDE

Everyone has a preference when it comes to integrated development environments (IDE).  I like PhpStorm but I use NetBeans because it’s free.  Once you set up your IDE, you can start coding.  There are plenty of good articles on using xdebug with popular IDEs for advanced debugging.  See the NetBeans wiki for information on how to use NetBeans and xdebug.

Profiling WordPress and Plugins

If you are interested in seeing how your WordPress plugins or patches are performing, consider running an xdebug profile.  You’ll need to edit php.ini again (click WampServer then php then php.ini), then change xdebug.profiler_enable_trigger to On and restart WampServer.  You can now trigger a profile by visiting http://localhost/wordpress-trunk/?XDEBUG_PROFILE=1.  This will log all performance information to a file in your c:\wamp\tmp folder.  You can view it by visiting http://localhost/webgrind/ or by opening the file in WinCacheGrind.

Note:  Using the method above, only URLs containing “?XDEBUG_ENABLED=1” will be profiled.  Hits to generated resources (e.g. wp-content/plugins/myplugin/script.js.php) will not be profiled!  You will need to use a tool like Xdebug Enabler for Chrome to automatically send the XDEBUG_PROFILE argument for every request.

Contributing

And lastly, make sure read the codex on contributing back to WordPress and consider giving back to the community.