Friday, May 31, 2013

Log4PHP not logging?

Do you use log4php? I am a big fan of the log4-* suite. It's great to have a consistent approach to logging across languages.

I've been using Log4PHP for almost a year now and aside from one issue with logging exceptions, I've had no problems with it and, in general, enjoy any time I've spent reading the source.

I had a bit of a problem today that was my own fault, but seems very possible for another to make. I've been happily using LoggerLayoutTTCC for some time. It was deprecated in the 2.3.0 release last October in favor of LoggerLayoutPattern. So I switched to LoggerLayoutPattern. Things have been humming along just fine, but something changed recently. I noticed today that none of my log entries were getting written. Only errors were getting written out, and they weren't using any identifiable format.

After digging into the source, I discovered that LoggerLayoutPattern had no parsed pattern. Effectively this means that when my appenders asked the layout class to format the message, it was returning an empty string, which was being thrown away and not logged.

How could this happen? The culprit was that although the LoggerLayoutPattern class has a default pattern, it is not applied by the constructor. Out of the box this would not be an issue, but since I had previously been using LoggerLayoutTTCC, which takes no constructor arguments, I was not passing in conversionPattern for the params argument to Logger::configure() when defining my appender.

The fix was straightforward: supply a conversion pattern! This feels like a minor bug with the Log4PHP code that should warn about the missing param or just use the defined default.

'appenders' => array(
 'default' => array(
  'class' => 'LoggerAppenderDailyFile',
  'params' => array('fileName' => 'logs/default.log'),
  'layout' => array(
   'class' => 'Bart\Log4PHP\LoggerLayoutTTCCWithException',
   'params' => array(
    'conversionPattern' => '%d %p pid:%t %c %m%n',
   )
  ),
 ),

Tuesday, May 21, 2013

Say Goodbye to PHP shell_exec() and PHP exec()

Dealing with the shell in PHP can be a pain. If you are executing anything more complicated than a no argument command with a one line string result, things start getting complicated.

To get started, if you want to check the return status of your commands, you need to pass a reference parameter to exec()! Ok, so it's not returning the command exit status, well then you might expect that it returns the command's output instead? Nope; the return value of exec()is actually the last line from the command's output. If you want to get the full output of the command, then you're looking at yet another reference parameter. And wait, which order do those references parameters go?

After you've got your parameters sorted out, what about escaping arguments for security and accuracy? For that, you're left manually using PHP's other global functions.

Alright, so now you've got a safe, accurate command. How do you know it works? You might want to test it, right? Well, if you want to test any of your code that uses exec(), you're looking at a rough road ahead because PHPUnit has no facility to let you make assertions against parameters passed by reference. Furthermore, if you have more than one call to exec, then you really have no way to stub results out of the box because you can't differentiate between calls to exec. I previously blogged about one approach I've taken to solving this -- http://asheepapart.blogspot.com/2012/10/testing-shell-methods-with-phpunit.htmlMockShell works alright, but it doesn't help us with escaping the command for security or accuracy.

Enter the Bart Command class. Command is a simple class that acts as a facade over a single shell command. It takes a variable number of arguments to its constructor, representing arguments to the shelled command. The first constructor arg is reserved for the actual command itself. Each shell argument is escaped and then substituted for placeholders in the shell command.

A command can be passed around and executed on demand. The results are returned as a full string or an array of each line. If the command fails, a custom exception of type is CommandException thrown.

We're using Command extensively in our internal code bases with a lot of success. Currently, you can see it used in a few places in the Git class.

I also created the gist below,


Testing is easy. There isn't any pass-by-reference magic, you can just apply all your standard testing know-how. You can use Diesel to inject your stub into your system under test. You can also mock the results of the shorthand Shell->command() method.

Monday, May 13, 2013

Bash Completion with SSH or SCP

I spend a lot of time ssh-ing around to the same machines. Using ~/.ssh/config helps me create nicknames for those hosts, but what's even better is bash completion. I created the following script to register the "ssh" and "scp" commands with bash completion so that I can just hit <TAB> to let bash complete the possible machine names.

I spent a lot of time reading up on how the bash completion system works and tried to make this script as clear as possible so that I can adopt the same strategy for future completion work.



Hope this helps!

Tuesday, May 7, 2013

CodeIgniter & PHP 5.4 -- Creating default object from empty value

I, sadly, use Code Igniter to power several of my legacy web applications. We recently upgraded our development environment PHP 5.4 and have not yet upgraded our production systems. We work with these apps infrequently in development and this hasn't been a problem. However, today I needed to test moving traffic from HTTP to HTTPS on one of the apps and kept receiving the several instances of the following message,

Severity: Warning
Message: Creating default object from empty value

Each of these warnings was linked to lines in my base controller (REST_Controller) that were performing assignments to properties of class fields. E.g. $this->rest->db = $this->load->database(...). I was unable to replicate the error on another machine running 5.3 and determined that my problem must be arising from PHP 5.4.

Code Igniter works in weird ways and my first guess was that some magic code or eval was failing due to the elevated strictness of PHP 5.4. So I embarked on a mission to discover where the class fields were being assigned inside Code Igniter. I scoured deep into CI_Config and CI_Loader and Code_Igniter.php, but couldn't find my answer; there were no magic methods or variable variable assignments. Feeling rather dejected, frustrated, and confused, I took another look at the error message: "creating default object from empty value" and an idea formed in my mind: what if PHP was telling me that it was in fact creating the class field right there on the spot?

The easiest way to test that theory was to create the object myself and test if the message still appeared. I updated the code to create the field just before each of the failing lines. E.g.

$this->rest = new stdClass();
$this->rest->db = $this->load->database(...);

And, voila -- no more warnings! So it turns out that the problem had little to do with Code Igniter itself, but just that historic PHP is way too friendly to lazy coders.

Now, with that out of the way, on to testing the HTTPS migration...