Make WordPress Core

Opened 8 weeks ago

Closed 7 weeks ago

Last modified 7 weeks ago

#60915 closed defect (bug) (fixed)

WP 6.5 - RecursiveDirectoryIterator causing E_WARNING errors in New Relic

Reported by: icaleb's profile iCaleb Owned by: joemcgill's profile joemcgill
Milestone: 6.5.2 Priority: normal
Severity: trivial Version: 6.5
Component: General Keywords: has-patch fixed-major dev-reviewed
Focuses: performance Cc:

Description

I apologize in advance for such an obscure bug, but hopefully at a minimum it'll at least provide some keywords that will be nice for others to come across and save them troubles when they go looking :)

The removal of file_exists() from here: https://github.com/WordPress/WordPress/commit/5b5e874ed5202e3b4355d74b5f7b24a5c6aaae0c, is essentially causing some phantom errors to bubble up in New Relic:

RecursiveDirectoryIterator::__construct(/var/www/wp-content/themes/theme-name/templates): Failed to open directory: No such file or directory
 in RecursiveDirectoryIterator::__construct called at /var/www/wp-includes/block-template-utils.php (233)
 in _get_block_templates_paths called at /var/www/wp-includes/block-template-utils.php (343)
 in _get_block_templates_files called at /var/www/wp-includes/block-template-utils.php (1023)
 in get_block_templates called at /var/www/wp-includes/block-template.php (140)
 in resolve_block_template called at /var/www/wp-includes/block-template.php (66)
 in locate_block_template called at /var/www/wp-includes/template.php (66)
 in get_query_template called at /var/www/wp-includes/template.php (515)
 in get_search_template called at /var/www/wp-includes/template-loader.php (81)
 in require_once called at /var/www/wp-blog-header.php (19)
 in require called at /var/www/index.php (17)

Calling RecursiveDirectoryIterator() with a folder that does not exist turns into an E_WARNING error as reported by New Relic. Now notably, calling it with a folder that doesn't exist is expected behavior and it throws an Exception: https://www.php.net/manual/en/recursivedirectoryiterator.construct.php. And the code is clearly catching that Exception and I can confirm it works. But despite that, it still turns into an E_WARNING error reported by New Relic >.<.

The issue can be replicated with something as simple as this (assuming NR is setup):

<?php
add_action( 'init', function() {
        try {
                new RecursiveDirectoryIterator( get_template_directory() . '/these-are-not-the-droids-you-are-looking-for' );
        } catch ( Exception $e ) {
                // Caught the exception. Otherwise the page would fatal (unless caught with a custom error handler).
        }
} );

Tried to do some digging, but unfortunately don't yet have any concrete answers. In PHP source, I did notice this along the path which could be related: https://github.com/php/php-src/blob/bb1688d732bd0ff749f6b31606be2ee63b47a284/ext/spl/spl_directory.c#L295. And in the NR APM, I confirmed it's coming out of here: https://github.com/newrelic/newrelic-php-agent/blob/2c9bf202e8479d76de3ab676500430b7509c89bf/axiom/nr_txn.c#L1633. Certainly feels like a NR agent issue, it must be picking up a signal from somewhere and interpreting it incorrectly. I'm following up with NR about this as well. But I've seen this be quite widespread and heard of it existing for other orgs as well, and it is causing a rather large and unfortunate amount of noise and alerting for users that upgrade to WP 6.5.

WP Core has been using RecursiveDirectoryIterator() for a while now, but this is the first time I believe it's used without first having an is_dir() or file_exists() check beforehand. I suppose we could add back the extra check, and with php file caching it should be more than okay. Admittedly annoying though.

Change History (16)

This ticket was mentioned in PR #6355 on WordPress/wordpress-develop by @sean212.


8 weeks ago
#1

  • Keywords has-patch added

Though https://core.trac.wordpress.org/ticket/58196 improved the performance of _get_block_templates_paths() in 77dcb1771ae14e655edaf514f0f55c28212d9bb2, this does throw a notice:

RecursiveDirectoryIterator::construct(/var/www/wp-content/themes/:theme/templates): Failed to open directory: No such file or directory

Trac ticket: https://core.trac.wordpress.org/ticket/60915

#2 @sean212
8 weeks ago

Was just looking into this notice from core and 6.5: spun up a potential fix here: https://github.com/WordPress/wordpress-develop/pull/6355

#3 @joemcgill
8 weeks ago

  • Keywords changes-requested added
  • Owner set to joemcgill
  • Status changed from new to reviewing

Thanks for the detailed report, @iCaleb. It's odd that New Relic is reporting these errors given that we've intentionally put this code inside a try/catch block. It seems like this could be related to this issue reported in the NR forums.

That said, I see how this could be annoying. Given that the removal of the file_exists check in [57215] was essentially a micro-optimization, it would be fine to revert that part of the change. I think using is_dir as @sean212 is suggesting in this PR is better than the previous file_exists check. I've left a suggestion here. Let me know what you both think.

If New Relic fixes this issue, or we can identify why it's happening and avoid having these types of expected handled errors being reported, then it would be nice to be able to avoid these types of filesystem checks, when possible.

@sean212 commented on PR #6355:


8 weeks ago
#4

@joemcgill thank you! I applied your feedback.

This ticket was mentioned in Slack in #core by jorbin. View the logs.


8 weeks ago

#6 @joemcgill
8 weeks ago

  • Resolution set to fixed
  • Status changed from reviewing to closed

In 57928:

Themes: Avoid errors in some environments from _get_block_templates_paths.

This adds an is_dir() check in _get_block_templates_paths before trying to run a RecursiveDirectoryIterator to avoid errors being reported in New Relic even thought the errors should be handled by a try/catch block.

Follow-up to [57215].

Props iCaleb, sean212, mukesh27, joemcgill.
Fixes #60915.

#7 @joemcgill
8 weeks ago

  • Keywords fixed-major added; changes-requested removed
  • Milestone changed from Awaiting Review to 6.5.1
  • Resolution fixed deleted
  • Status changed from closed to reopened

Reopening to backport to the 6.5 branch.

#8 @jorbin
8 weeks ago

  • Keywords dev-reviewed added

[57928] looks good for backport to 6.5

#9 @mboynes
8 weeks ago

I was looking into this yesterday as well and found a couple of possibly-related links discussing the NR agent, which I'll share here for posterity:

We encountered (unrelated) segfaults updating the agent to 10.19, so I can't confirm if that version resolves this or not.

#10 @joemcgill
7 weeks ago

  • Resolution set to fixed
  • Status changed from reopened to closed

In 57947:

Themes: Avoid errors in some environments from _get_block_templates_paths.

This adds an is_dir() check in _get_block_templates_paths before trying to run a RecursiveDirectoryIterator to avoid errors being reported in New Relic even thought the errors should be handled by a try/catch block.

Follow-up to [57215].

Reviewed by jorbin.
Merges [57928] to the to the 6.5 branch.

Props iCaleb, sean212, mukesh27, joemcgill.
Fixes #60915.

#11 @joemcgill
7 weeks ago

Thanks @mboynes!

It really does seem like an NR issue that is causing these caught exceptions to still show up in reports. It's easy enough for us to avoid in this case, but I would expect there to be other occasions where we might want to avoid unnecessary file checks and instead attempt to read a file inside a try/catch block like this.

#12 @davidbaumwald
7 weeks ago

  • Milestone changed from 6.5.1 to 6.5.2

Milestone renamed

#13 @lucasbustamante
7 weeks ago

I started seeing the same errors 1 month ago, while using the RC releases of 6.5, and I was waiting to see if a ticket like this would pop up, because at the time I couldn't track it down.

By looking at the logic, the only possible explanation was an outdated PHP stat cache on WP_FileSystem::dirlist() method, because a file that had been deleted was passing is_file check, which uses the stat cache. I'm not familiar with the micro-optimization that introduced this bug, but it was probably aimed at reducing disk reads by leveraging the stat cache? Again, I'm not familiar with the code, but maybe we could keep the optimization and lazy-load the disk read, by having a clearstatcache in that method - hopefully that's enough?

https://app.slack.com/client/T024MFP4J/C02RQBWTW

#14 @lucasbustamante
7 weeks ago

Although, now that I've read the PR associated with this Trac Ticket, it seems that the issue in WPFilesystem::dirlist() has no relation with what is being discussed here, actually...

#16 @iCaleb
7 weeks ago

Thanks all for helping patch this and preventing the phantom errors :)

Fix & explanation relating to the NR agent can be found here: https://github.com/newrelic/newrelic-php-agent/pull/876

Note: See TracTickets for help on using tickets.