Tag: PHP

We came across this PHP bug at work today.  But before you go and read it, let me show you a use case.  See, if you can spot the problem.

We had a cron job script which looked something like this (shortened for clarity):

#!/bin/bash

# ... a bunch of stuff here ... 

date && echo "Updating products"
php updateProducts.php 1>/dev/null

if [ "$?" -ne "0" ]
then
  date && echo "Updating products failed"
  exit 1
fi

# ... more stuff here ...

Crystal clear, no? Output a time stamp and a log message, run the product update, redirecting all normal output to standard output, and then check if the script finished fine. If not, print the time stamp and log message and exit with non-zero status code.

We use similar code snippets all over the place, and they work fine.  This particular one was a new addition.  So the cron job ran and “Updating products failed” part happened.  Weird.   The PHP script in question has plenty of logging in it, but nothing was logged.  So we added more logs.  And then some more logs.  And even more logs.  Until it became obvious that something else is wrong, because even the first line of the script, which was now a logging action, wasn’t triggered.

After a rather lengthy troubleshooting session we noticed that the updateProducts.php file was in fact named udpateProducts.php.  A simple typo in the file name.  But shouldn’t that be printed out into the error output?

Let’s check:

$ php no_such_file.php
Could not open input file: no_such_file.php
$ php no_such_file.php 1>/dev/null
$

Huh? Where’s my error? It’s gone.   That’s because if you are as used to the command line as I am, you’d expect PHP to output to STDERR.  But PHP is much smarter than that.  It has a whole slew of configuration options in regards to error output.  In this case, in particular, you need to check the values of display_errors and error_log configuration variables.  The bug report describes a Debian machine, while I tested it on Fedora, CentOS, and Amazon AMI.

$ php -i | egrep '(display_errors|error_log)'
display_errors => Off => Off
error_log => no value => no value

Now it’s not much of a mystery.  But things like that can easily make you pull some hair out.  Hopefully, this gets some attention.

“Logging with Monolog: From Devtools to Slack” is a handy quick article for anybody who wants to use Monolog for logging in PHP applications.  After all, monolog/monolog is one of the most popular libraries on Packagist.

“An Exceptional Change in PHP 7.0” blog post describes nicely what are the changes to exceptions and error handling in the upcoming PHP 7.  Among simple descriptions, there is this reference chart:

\Throwable
├── \Exception (implements \Throwable)
│   ├── \LogicException (extends \Exception)
│   │   ├── \BadFunctionCallException (extends \LogicException)
│   │   │   └── \BadMethodCallException (extends \BadFunctionCallException)
│   │   ├── \DomainException (extends \LogicException)
│   │   ├── \InvalidArgumentException (extends \LogicException)
│   │   ├── \LengthException (extends \LogicException)
│   │   └── \OutOfRangeException (extends \LogicException)
│   └── \RuntimeException (extends \Exception)
│       ├── \OutOfBoundsException (extends \RuntimeException)
│       ├── \OverflowException (extends \RuntimeException)
│       ├── \RangeException (extends \RuntimeException)
│       ├── \UnderflowException (extends \RuntimeException)
│       └── \UnexpectedValueException (extends \RuntimeException)
└── \Error (implements \Throwable)
    ├── \AssertionError (extends \Error)
    ├── \ParseError (extends \Error)
    └── \TypeError (extends \Error)

Very handy!

I’ve been coding PHP for a few years now, but still once in a while I come across something that I had no idea about.  In a recent project I was working on the single sign on (SSO) integration with the customer’s internal systems.  After doing the initial proof of concept code snippet, I got the logged in user results from a shared caching server.  The string looked something like this:

UserAuth|a:2:{s:8:"username";s:6:"leonid";s:4:"role";s:5:"admin";}UserSettings|a:2:{s:8:"language";s:2:"en";s:8:"timezone";s:5:"GMT+2";}

This was very similar to the results of PHP’s serialize() function, but not quite.  I’ve asked around, but nobody could point me in the right direction, so I went the regular expression way to parse this (do I have two problems now?).

After a code review and discussion with the developers on the customer side, I’ve learned that this is apparently a result of PHP’s session_encode() function, which I haven’t seen in the wild until that day.  Excellent! Now I should be able to use session_decode() to parse that, right?  Well, almost.  According to PHP Sadness #29:

The only way to decode php-session-format serialization (different from normal php serialize) is by calling php session_decode, which can only be called if there is an active session. If there is no active session, you can’t decode session data without starting one first.

So, don’t forget to session_start() before you try to decode.  Which makes it a bit tricky if you already have a session that you don’t want to ruin.  You might want to look into session_name() to work around it.  Gladly, I didn’t have to resolve to that as another customer-specific work around was implemented.