14 Aug

Segfaults in Drupal are not a common occurrence - but when they do pop up, they can pose some tricky challenges... Our DevOps Engineer Mattias Michaux sheds some light on how to debug segmentation faults.
 

As a Drupal web developer, it can be frightening to encounter a so-called segmentation fault or segfault. This is a type of failure raised by hardware with memory protection, notifying you that the software has attempted to access a restricted area of memory. This kind of fault is common in languages with low-level memory management, such as C. Coding in a scripting language like PHP usually implies that you will be spared from segfaults, but on rare occasions these kind of errors can still pop up. And if they do, they tend to leave no stack trace or meaningful error clue in the PHP log. This is because segfault errors originate in the layers located below the PHP engine. Let me talk you through a recent consulting project that involved a curious segmentation fault.
 

Segfault case study

Not so long ago, one of our clients started experiencing seemingly random ‘503 service unavailable’ errors, at random times on random pages. That’s plenty of randomness, without much of a clue to start from.
 

The segfaults had started occurring after an update from PHP 5.6 to PHP 7.2 and the switch from mod_php - PHP is executed as a module within the Apache process -  to PHP-FPM. Just to clarify: PHP runs as a standalone service that Apache connects to.
 

We tried to reproduce the errors on a copy of the site and infrastructure of the project. The segfault was only reproducible when we ran a scraping tool on the site. There was no apparent connection between the pages it occurred on, and the error came up with less than 1% of the total requests. Looking at the logs, there seemed to be no direct cause for this error.

[proxy_fcgi:error] [pid 10272] AH01067: Failed to read FastCGI header[proxy_fcgi:error] [pid 10272] (104)Connection reset by peer: AH01075: Error dispatching request to ****

Example of the unhelpful Apache error message

The message above only tells us that something went wrong, but it provides no indication as to what the cause might be. Next, the PHP-FPM log indicated a segmentation fault:

WARNING: [pool web] child 3824 exited on signal 11 (SIGSEGV) after 3.353763 seconds from start

The syslog entry didn’t turn out to be very helpful either:

kernel: [4734894.041892] traps: php-fpm7.2[3760] general protection ip:555ce4cb6342 sp:7ffccab418c8 error:0kernel: [4734894.041897]  in php-fpm7.2[555ce4a51000+411000]

To find out what the root cause might be, we needed to recompile PHP with debugging enabled. This allowed us to produce core dumps, which contain a full backtrace. A backtrace is a summary of how the program got to a particular point. It displays one line per frame for many frames, starting with the frame that is currently being executed. I suggest finding a guide like this one on how to compile your php with debugging enabled.
 

After compiling PHP, we copied the php.ini and pool config from the original PHP version to the freshly compiled one. Next, we altered the config, so now the PHP-FPM pool used a separate name and socket path, and we changed that socket in the vhost. After starting the new PHP-FPM instance and running the crawler to reproduce the issue, we quickly saw the same 503 errors showing up, but this time with a core dump. We started comparing the dumps and tried to find a pattern. Fortunately, most cases pointed to the same thing: the unserialize() function of large objects. This made us look for specific PHP bugs that involved unserializing or memory allocation. We found an interesting one - in fact, someone had encountered almost the same issue before.
 

We decided to try the same approach by disabling garbage collection in the settings file:

ini_set('zend.enable_gc', 0);

We reran the scraper for multiple hours and no issues occurred. There are other documented cases where PHP’s garbage collection interferes with Drupal’s processing of huge amounts of data and objects.  Because disabling the garbage collection globally could have negative effects on the resource consumption of the live site, we also looked for a way to only disable garbage collection partially. This is indeed possible by patching  includes/cache.inc so _cache_get_object doesn’t run gc while fetching data.
 

This puzzling problem took several hours and two people to solve, but in the end we managed to diagnose correctly and we implemented a solid solution. An interesting case that led us to explore unusual parts of Drupal - and possibly something to bear in mind next time your Drupal environment produces a similar type of error.
 

gdb /opt/php/7.2/sbin/php-fpm /tmp/coredump-php-fpm.28651 -ex "source /opt/php-src/php7.2-build/php-7.2.17/.gdbinit" -ex "zbacktrace" --batch | grep "\[0x"

[0x7f2c2b4220e0] unserialize("O:4:"view":49:{s:8:"db_table";s:10:"views_view";s:10:"base_table";s:18:"commerce_line_item";s:10:"base_field";s:3:"nid";s:4:"name";s:25:"commerce_reports_products";s:3:"vid";s:0:"";s:11:"description";s:0:"";s:3:"tag";s:16:"commerce_reports";s:10:"human_nam...") [internal function][0x7f2c2b421f40] DrupalDatabaseCache->prepareItem(object[0x7f2c2b421f90]) /home/project/www/includes/cache.inc:520[0x7f2c2b421d80] DrupalDatabaseCache->getMultiple(reference) /home/project/www/includes/cache.inc:433[0x7f2c2b421cf0] cache_get_multiple(reference, "cache_views") /home/project/www/includes/cache.inc:113[0x7f2c2b421a70] _ctools_export_get_defaults_from_cache("views_view", array(24)[0x7f2c2b421ad0]) /home/project/www/sites/all/modules/contrib/ctools/includes/export.inc:746[0x7f2c2b421390] _ctools_export_get_defaults("views_view", array(24)[0x7f2c2b4213f0]) /home/project/www/sites/all/modules/contrib/ctools/includes/export.inc:649[0x7f2c2b4211a0] _ctools_export_get_some_defaults("views_view", array(24)[0x7f2c2b421200], array(1)[0x7f2c2b421210]) /home/project/www/sites/all/modules/contrib/ctools/includes/export.inc:783[0x7f2c2b420210] ctools_export_load_object("views_view", "names", array(1)[0x7f2c2b420280]) /home/project/www/sites/all/modules/contrib/ctools/includes/export.inc:493[0x7f2c2b420080] ctools_export_crud_load("views_view", "search_results") /home/project/www/sites/all/modules/contrib/ctools/includes/export.inc:81[0x7f2c2b41ff50] views_get_view("search_results") /home/project/www/sites/all/modules/contrib/views/views.module:1683[0x7f2c2b41fb50] views_block_view("-exp-search_results-page") /home/project/www/sites/all/modules/contrib/views/views.module:772[0x7f2c2b41fa60] module_invoke("views", "block_view", array(1)[0x7f2c2b41fad0]) /home/project/www/includes/module.inc:934[0x7f2c2b41f410] _block_render_blocks(array(0)[0x7f2c2b41f460]) /home/project/www/modules/block/block.module:911[0x7f2c2b41f2d0] block_list("branding") /home/project/www/modules/block/block.module:690[0x7f2c2b41f200] block_get_blocks_by_region("branding") /home/project/www/modules/block/block.module:319[0x7f2c2b41eee0] block_page_build(reference) /home/project/www/modules/block/block.module:270[0x7f2c2b41ecf0] drupal_render_page(reference) /home/project/www/includes/common.inc:5914[0x7f2c2b41e570] drupal_deliver_html_page(array(1)[0x7f2c2b41e5c0]) /home/project/www/includes/common.inc:2761[0x7f2c2b41e3d0] drupal_deliver_page(array(1)[0x7f2c2b41e420], "") /home/project/www/includes/common.inc:2634[0x7f2c2b41e100] menu_execute_active_handler() /home/project/www/includes/menu.inc:542[0x7f2c2b41e030] (main) /home/project/www/index.php:21

dropsolid8