Make WordPress Core

Opened 3 years ago

Closed 2 years ago

#53493 closed enhancement (fixed)

Errors in `ms-files.php` aren't logged

Reported by: iandunn's profile iandunn Owned by: iandunn's profile iandunn
Milestone: 5.9 Priority: low
Severity: normal Version: 3.0
Component: Upload Keywords: early has-patch needs-testing
Focuses: multisite Cc:

Description

r12936 added error_reporting(0) to ms-files.php. This makes troubleshooting problems like #53492 much harder.

I haven't groked #11742 yet, but 11742.2.diff describes the reason as:

Sets error_reporting to 0, removing requirement for a new SHORTLOAD constant and error suppression operators.

My guess is that the goal is to prevent PHP notices/warnings from breaking the image output. That makes sense, but it could be accomplished with ini_set( 'display_errors', 'off' ), without hiding errors from logs.

Change History (18)

#1 @iandunn
3 years ago

ticket:11742#comment:8 adds more context. Before 11742.2.diff, 11742.diff had taken this approach:

In order to be completely backwards compatible, I needed to create a new SHORTLOAD constant that is identical to SHORTINIT. This prevents an existing blogs.php drop-in that defines SHORTINIT from generating an unsuppressed E_NOTICE for redefining a constant.

So when error_reporting(0) was added in 11742.2.diff, the goal was really just to hide those specific notices.

However, 12742.5.diff intended it to hide all notices, similar to what the REST API, admin-alax.php, and XML-RPC do today:

Return error_reporting(0) to ms-files.php, reverting [13038]. Remove deprecated warnings as it breaks media file handling, and no translation support exists, reverting part of [12977].

#2 @iandunn
3 years ago

  • Keywords early has-patch needs-testing added
  • Milestone changed from Awaiting Review to 5.9
  • Owner set to iandunn
  • Status changed from new to accepted

Added a PR in https://github.com/WordPress/wordpress-develop/pull/1437, but it doesn't look like prbot pulled it in.

FYI @desrosj, @noisysocks

#3 @iandunn
3 years ago

it doesn't look like prbot pulled it in

Oh, it looks like it saw two Trac links, and chose the first and ignored the second. That makes sense.

#4 @iandunn
3 years ago

#53492 has reproduction steps

#5 @iandunn
3 years ago

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

In 51358:

Multisite: Log error/warnings/notices from ms-files.php.

Previously errors were not displayed or logged, but the original intention was only to prevent them from being displayed. Hiding them from logs makes problems like #53492 much harder to debug.

This makes the handling of errors in ms-files consistent with the REST API, admin-ajax, and XML-RPC.

Props iandunn, johnjamesjacoby.
Fixes #53493.

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


2 years ago

#7 @hellofromTonya
2 years ago

  • Resolution fixed deleted
  • Status changed from closed to reopened

Reopening as errors reported during installation, see #54801. As 5.9 is in RC and this bug was not introduced in the 5.9 cycle, I propose reverting [51358] and moving to 6.0 cycle for further testing, db audit, and resolution with plenty of alpha/beta/rc soak time.

#8 follow-up: @iandunn
2 years ago

Yeah, reverting sounds good to me if that's the most practical option. I am a confused by a few things, though:

  • r51358 was only supposed to enable logging errors, not displaying them. Has this been reproduced in a browser, or just WP-CLI? If it's only WP-CLI, then it may be related to how it doesn't always respect WP_DEBUG.
  • The change should also only effect ms-files.php (multisite media proxying), which doesn't seem related to wp core is-installed. Does reversing this commit locally fix that CLI command?
  • The change was committed 6 months ago, at the start of the 5.9 cycle, so it seems odd that it wasn't discovered until just now.

Regardless, though, the most important thing is a smooth release, so if y'all are confident then reverting sounds good.

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


2 years ago

#10 in reply to: ↑ 8 @schlessera
2 years ago

Let me try to reply to the questions above.

Replying to iandunn:

  • r51358 was only supposed to enable logging errors, not displaying them. Has this been reproduced in a browser, or just WP-CLI? If it's only WP-CLI, then it may be related to how it doesn't always respect WP_DEBUG.

What the change does is to go from suppressing errors in a specific context to not suppressing errors in a specific context. Whether they are sent to the logs, displayed or manipulated in some other way depends on the environment. However, no matter what the environment is, the previous behavior was to "not have errors at all", which now changed.

  • The change should also only effect ms-files.php (multisite media proxying), which doesn't seem related to wp core is-installed. Does reversing this commit locally fix that CLI command?

Yes, reverting the commit fixes that command. The errors appear as soon as the MULTISITE define is found in the wp-config.php, which triggers loading the ms-files.php. Then, the multisite bootstrapping is supposed to figure out the exact topology from the database, which throws WPDB errors depending on the state of the site. These errors were always present, what were suppressed. The DB calls in Core that can potentially fail with an error but are necessary are all wrapped in a $wpdb->suppress_errors() structure, except for the multisite one in question here, as no one noticed they produced errors due to the error_reporting( 0 ).

  • The change was committed 6 months ago, at the start of the 5.9 cycle, so it seems odd that it wasn't discovered until just now.

I have seem them much earlier, but the combination of PHP 8.1 and latest Core trunk has had so many breaking changes that it took quite a while to distill everything and figure out the root cause for everything. In the beginning, I assumed it was a typing error or similar.

#11 follow-up: @iandunn
2 years ago

Ah, I see, thanks! 👍🏻

The only thing that still doesn't make sense to me is this:

The errors appear as soon as the MULTISITE define is found in the wp-config.php, which triggers loading the ms-files.php.

The only entrypoint I see to ms-files.php is by calling it directly w/ the /files/ rewrite endpoint.

But it sounds like you're saying it's include'ed by wp-load.php / ms-load.php? I'm sure you're right, I'm just curious about what I'm missing.

#12 in reply to: ↑ 11 ; follow-up: @schlessera
2 years ago

Replying to iandunn:

The errors appear as soon as the MULTISITE define is found in the wp-config.php, which triggers loading the ms-files.php.

The only entrypoint I see to ms-files.php is by calling it directly w/ the /files/ rewrite endpoint.

Hmm, you're right, there's no reason why that should be triggered... Guess I have to continue the investigation!

#13 @hellofromTonya
2 years ago

Where do this stand for RC3? Tomorrow is currently the last RC release before final next week. Reverting removes the reported issue, though doesn't truly fix it.

@schlessera have you found more information?

#14 @iandunn
2 years ago

🤔, I'm not seeing the error locally w/ WP-CLI 2.5.0 and 5.9-beta4-52408-src. That's w/ PHP 8.0.6 and Multisite.

What are the steps/conditions to reproduce?

#15 @hellofromTonya
2 years ago

Re-reading @schlessera description in #54801, the 2 db errors are triggered on empty sites when using wp core is-installed command. @iandunn what happens for you when using this command?

#16 @iandunn
2 years ago

Ah, my bad, I was trying it w/ a DB_NAME that hadn't been created yet. The db needs to exist, but not have the WP tables in it. Thanks!

With that, I can see an error, but there're some differences from Alain's screenshot. I only see the wp_blogs error, not the wp_sitemeta one; and the stack trace is absent.

> wp core is-installed
Error: WordPress database error: [Table 'misc.wp_blogs' doesn't exist]
SELECT  wp_blogs.blog_id FROM wp_blogs  WHERE domain = 'wp-develop.test' AND path = '/'  ORDER BY wp_blogs.blog_id ASC LIMIT 1

I tried reverting r51358, but that didn't hide the error for me. I tried reverted back to 5.6 and still saw the error.

I also tried putting exit() statements in ms-files.php and wp_debug_mode(), to verify that they weren't being called, and neither statement was triggered. That makes sense, since ms-files.php is unrelated, and WP-CLI uses it's own error handling. Those are the only two things that r51358 touched, though.

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


2 years ago

#18 in reply to: ↑ 12 @hellofromTonya
2 years ago

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

Replying to schlessera:

Replying to iandunn:

The errors appear as soon as the MULTISITE define is found in the wp-config.php, which triggers loading the ms-files.php.

The only entrypoint I see to ms-files.php is by calling it directly w/ the /files/ rewrite endpoint.

Hmm, you're right, there's no reason why that should be triggered... Guess I have to continue the investigation!

As @schlessera and @iandunn discussed, changeset [51358] does not seem to be the root cause of the issue reported in #54801. And in additional investigative testing, @costdev and @peterwilsoncc also found db errors are reproducible going back to at least 4.2.

Reclosing this ticket as fixed. Thank you everyone for your care in discussing and investigating this issue.

Note: See TracTickets for help on using tickets.