Sometimes running is good :)

We have started migrating sites off of DreamHost. To make sure we have the procedure correct so that we don’t cause any customer interruptions we started with our own site.

The new site is a fresh, untuned Apache instance residing on a clean Digital Ocean Droplet. Check out the performance gain!

slow-dh

Having been forced to take action due to the DreamHost debacle it’s nice to see some positive impacts.

I wonder how much better the new site will be after some performance tuning?

And no, still no response from DreamHost support and management about their planned lockout of their customers

Diagnosing a WP eCommerce Error on GoDaddy Hosting with PHP APC

Recently there were a flurry of bug reports about a fatal error in WP eCommerce in the WordPress support forum. Initially all of the reports were from sites using GoDaddy for hosting. The common cause for the bug reports was a fatal PHP error that looks something like this:

Fatal error: WPSC_Countries::get_countries(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition "WPSC_Data_Map" of the object you are trying to operate on was loaded _before_ unserialize() gets called or provide a __autoload() function to load the class definition in /home/content/p3nexnas05_data03/62/2100362/html/wp-content/plugins/wp-e-commerce/wpsc-includes/wpsc-countries.class.php on line 462
Fatal error: WPSC_Countries::_dirty(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition "WPSC_Data_Map" of the object you are trying to operate on was loaded _before_ unserialize() gets called or provide a __autoload() function to load the class definition in /home/content/p3nexnas05_data03/62/2100362/html/wp-content/plugins/wp-e-commerce/wpsc-includes/wpsc-countries.class.php on line 1142

Justin from the WP eCommerce team, quickly figured out that if you turn off WordPress object caching the problem goes away.

The sites in question were asked to install the free WP eCommerce Site Checkup Plugin. On all of the sites checked, the plugin reported information that was helpful in getting started.

Triage of the reports told us a couple of things:

  1. Only seems to happen when APC op-code cache is being used as a WordPress Object Cache.
  2. Issue is highly intermittent
  3. Site checkup reports that APC is part of the PHP configuration
  4. Site checkup reports that WordPress doesn’t think APC is installed as an object cache
  5. Site checkup reports that WordPress doesn’t think an object cache is active.

An easy workaround for the issue is to rename the object-cache.php to something like “_object-cache.php”.  This stops the APC cache from being used as a WordPress object cache.

Because the error was only occurring in production environments, and was very intermittent stepping through in the debugger was not an option. Next best thing was the WordPress developer’s tried and tried method of using WordPress’ debug.log file, and embedding “error_log” calls at strategic places in the code to see what was going on.

We Need To Pass the Site Checkup Object Cache Test

After a couple of strategically placed logging calls showed that the object cache was only being enabled for user facing pages a read through of all of the code in object-cache.php began.  The object-cache.php was from a plugin written by WordPress Guru Mark Jaquith. Because the plugin has been around for at least 5 years, and was written by Mark, anyone would pretty much assume that the issue wasn’t inside the plugin.  But after several trips away from the code, the logging continued to point to something odd going on. Most notable, was that the object cache test in the site checkup plugin was always failing.

Finally, after a no-assumptions careful review of the APC object-cache plugin code, a test was shown to be intentionally stopping the object cache from loading on any admin request.

$oc_blocked_page = ( defined('WP_ADMIN') || defined( 'DOING_AJAX' ) || defined( 'XMLRPC_REQUEST' ) || defined( 'DOING_CRON' ) || 'wp-login.php' === basename( $_SERVER['SCRIPT_FILENAME'] ) );
if ( 'cli' !== php_sapi_name() && function_exists( 'apc_fetch' ) && !$oc_logged_in && !$oc_blocked_page ) :

Because admin requests include anything the store checkup plugin was doing, it explains why the diagnostics are failing.  It also explains why some WP eCommerce configuration options managed by the administrator in the WordPress dashboard were not being updated for the users.  Without the object cache active when the administrator does work cached values would not be refreshed. This would result in stale or invalid data being available to end users, even though it was updated for administrators. The problem would extend to include any WordPress transients that are stored into the object cache when an object cache is enabled. It would also certainly include any value manipulated by an AJAX request or a scheduled CRON.

Changing the test used to decide if the object cache should be loaded to something less specific was easy. Change the condition to check for the presence of the APC extension:

if ( extension_loaded( 'apc' ) ) :

With the APC object cache test passing, and the object cache always available we changed the symptoms of our problem.  Instead of the PHP fatal error being intermittent, it happened all of the time.  I guess that’s progress?

Why Can’t WordPress Load WP eCommerce’s Data?

Remember that the WP eCommerce plugin operates perfectly without an APC object cache and operates perfectly with a Memcached (the daemon) based object cache. But as soon as we turn on APC as an object cache we see get the fatal error.

Because the fatal error was telling us that a class definition was not loaded , the first thing was to confirm that the key classes were being included in the application.  At the top of each PHP file, prior to the class being defined, we put an error log statement to record that the file has been included.  At the top of the file that defined the WPSC_Country class the statement:

error_log( ‘including class WPSC_Country’ );

was added.  At the top of the file that defined the WPSC_Countries class the statement:

error_log( ‘including class WPSC_Countries’ );

was added. At the top of the file that defined the WPSC_Data_Map class the statement

error_log( ‘including class WPSC_Data_Map’ );

was added.  Then a click on the page refresh button in our browser, and a look into the debug.log file. This is what was there:

[12-Apr-2015 23:53:03 UTC] including class WPSC_Country [12-Apr-2015 23:53:03 UTC] including class WPSC_Countries [12-Apr-2015 23:53:03 UTC] including class WPSC_Data_Map [12-Apr-2015 23:53:03 UTC] WPSC_Countries::__construct [12-Apr-2015 23:53:03 UTC] PHP Fatal error: WPSC_Countries::new_get_countries(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition “WPSC_Country” of the object you are trying to operate on was loaded before unserialize() gets called or provide a __autoload() function to load the class definition in /home/content/p3pnexwpnas03_data02/88/2349788/html/wp-content/plugins/wp-e-commerce/wpsc-includes/wpsc-countries.class.php on line 484

Reading the error message it really makes little sense.  The classes are included, then PHP cant find the class definition. Puzzling.

Next experiment was to create a PHP class autoloader, the error message seems to suggest this as a solution. This was added to the plugin code:

function wpsc_class_autoload( $class ) {

   $file = strtolower( str_replace( '_', '-', $class ) );
   error_log( __FUNCTION__ . ' class is ' . $class );

   if ( file_exists( WPSC_FILE_PATH . '/wpsc-includes/' . $file . '.class.php' ) ) {
      require_once( WPSC_FILE_PATH . '/wpsc-includes/' . $file . '.class.php' );
   }
}

error_log( 'autoload register' );
spl_autoload_register( 'wpsc_class_autoload' );
Make note of the error_log call in the autoloader callback function. This should record every request for class autoloading.

Another click of the browser refresh button produced another interesting log snippet:

[13-Apr-2015 10:16:57 UTC] including class WPSC_Country
[13-Apr-2015 10:16:57 UTC] including class WPSC_Countries
[13-Apr-2015 10:16:57 UTC] autoload register
[13-Apr-2015 10:16:57 UTC] including class WPSC_Data_Map
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is Sputnik
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is Sputnik_Admin
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is Sputnik_Updater
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is Sputnik_Pointers
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Module
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is external_links_anchor_utils
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is SitePress
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is WPML_Translation_Management
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is WC_Download_Handler
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Module_Manager
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Feature_Manager
[13-Apr-2015 10:16:57 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Performance
[13-Apr-2015 10:16:57 UTC] WPSC_Countries::__construct
[13-Apr-2015 10:16:57 UTC] PHP Fatal error:  WPSC_Countries::get_countries(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition "WPSC_Country" of the object you are trying to operate on was loaded _before_ unserialize() gets called or provide a __autoload() function to load the class definition  in /home/content/p3pnexwpnas03_data02/88/2349788/html/wp-content/plugins/wp-e-commerce/wpsc-includes/wpsc-countries.class.php on line 477

Notice that many classes are recorded as looking for an autoloader, but none of the WP eCommerce classes are requested!

Something was going on where WordPress, APC or PHP was trying to parse the contents of one of our cached values. But fatally failing.

Next experiment was to try to stop APC and PHP from parsing our stored value. Easy enough to do by encoding the cached value so that it wouldn’t be seen as an object by the system code. These functions were created to save and recall the cached value.

function special_set_transient(  $transient, $value, $expiration = 0 )  {
    $value = base64_encode( serialize( $value ) );
    return set_transient( $transient, $value, $expiration );
}

function special_get_transient( $transient )  {
    $value = get_transient( $transient );
    $value = base64_decode( $value );
    $value = maybe_unserialize( $value );
    if ( empty( $value ) ) {
        $value = false;
        delete_transient( $transient );
    }

    return $value;
}

The expectation was that this would not have any effect on the issue. But, that was not the case. This is what was in the log file after many page refresh requests:

[13-Apr-2015 11:28:36 UTC] including class WPSC_Country
[13-Apr-2015 11:28:36 UTC] including class WPSC_Countries
[13-Apr-2015 11:28:36 UTC] autoload register
[13-Apr-2015 11:28:36 UTC] including class WPSC_Data_Map
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is Sputnik
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is Sputnik_Admin
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is Sputnik_Updater
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is Sputnik_Pointers
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Module
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is external_links_anchor_utils
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is SitePress
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is WPML_Translation_Management
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is WC_Download_Handler
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Module_Manager
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Feature_Manager
[13-Apr-2015 11:28:36 UTC] wpsc_class_autoload class is All_in_One_SEO_Pack_Performance
[13-Apr-2015 11:28:36 UTC] WPSC_Countries::__construct
[13-Apr-2015 11:28:37 UTC] wpsc_class_autoload class is JQueryColorboxFrontend
[13-Apr-2015 11:28:37 UTC] wpsc_class_autoload class is Flattr
[13-Apr-2015 11:28:37 UTC] wpsc_class_autoload class is BJLL

No fatal PHP errors, not even any warnings.

Conclusions

  1. We have a fix to the object-cache.php and a potential change in WP eCommerce that will get us by the issue.
  2. The work-around that let’s WP eCommerce work in an environment that uses  APC as an object cache  seems to tell us there is an APC/PHP bug when retrieving cached objects that contain other objects from a WordPress APC object cache.

Is this a bug? Please give us your thoughts?