Problem/Motivation

In the BigPipe D8.1 core issue, @dawehner said this at #2469431-212: BigPipe for auth users: first send+render the cheap parts of the page, then the expensive parts:

+++ b/core/modules/big_pipe/src/Render/BigPipe.php
@@ -0,0 +1,432 @@
+      $fake_request = $this->requestStack->getMasterRequest()->duplicate();
+      $this->requestStack->push($fake_request);
+      $event = new FilterResponseEvent($this->httpKernel, $fake_request, HttpKernelInterface::SUB_REQUEST, $html_response);
+      $this->eventDispatcher->dispatch(KernelEvents::RESPONSE, $event);
+      $this->requestStack->pop();

I'm wondering whether we need to try catch here and reset the request stack in case some exceptions are thrown inside.

The obvious conclusion to jump to after reading that is: when something goes wrong when rendering placeholders, things will break badly. But that's actually not what that code does, it doesn't render placeholders. That happens earlier! So we should also wrap the code responsible for doing that in a try…catch.

The code that @dawehner quotes actually can only be broken if some response event subscriber throws an exception. This of course should also be tested.

Broken logic to render a placeholder is probably 100 times more common than a broken response event subscriber. So, let's also address that here too.

Proposed resolution

Broken logic to render a placeholder
  1. Add test case that explicitly throws an exception while rendering the placeholder.
  2. Verify that in production (non-verbose error logging), the exception is caught and not shown to the end user, that placeholder is then simply not shown
  3. Verify that in development (verbose error logging), the exception is not caught and shown to the end user, to not get in the way of the developer doing debugging
Broken response event subscriber
Same, but for an exception thrown in a response event subscriber, not while rendering a placeholder.

Remaining tasks

  1. Handle broken placeholder rendering
  2. Handle broken response event subscriber
  3. Reviews
  4. Commit

User interface changes

When

API changes

None.

Data model changes

None.

Comments

Wim Leers created an issue. See original summary.

wim leers’s picture

Issue summary: View changes
Status: Active » Needs review
StatusFileSize
new18.83 KB
wim leers’s picture

StatusFileSize
new19.54 KB
new945 bytes
wim leers’s picture

StatusFileSize
new18.17 KB
new6.57 KB

Clean-up.

Status: Needs review » Needs work

The last submitted patch, 4: 2678568-4.patch, failed testing.

wim leers’s picture

Issue summary: View changes
Status: Needs work » Needs review
StatusFileSize
new28.22 KB
new15.35 KB
new15.35 KB

As of this reroll, the logic is in place to handle broken response event subscribers.

This issue is now blocked on reviews.

wim leers’s picture

Project: BigPipe » Drupal core
Version: 8.x-1.x-dev » 8.1.x-dev
Component: Code » big_pipe.module
wim leers’s picture

StatusFileSize
new29.13 KB

Rerolled now that BigPipe is in core.

fabianx’s picture

Status: Needs review » Reviewed & tested by the community

RTBC - looks good to me.

Version: 8.1.x-dev » 8.2.x-dev

Drupal 8.1.0-beta1 was released on March 2, 2016, which means new developments and disruptive changes should now be targeted against the 8.2.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

wim leers’s picture

Version: 8.2.x-dev » 8.1.x-dev

The last submitted patch, 6: 2678568-5.patch, failed testing.

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 8: 2678568-8.patch, failed testing.

wim leers’s picture

Status: Needs work » Reviewed & tested by the community
StatusFileSize
new29.17 KB

Straight reroll.

alexpott’s picture

Status: Reviewed & tested by the community » Needs work
+++ b/core/modules/big_pipe/src/Tests/BigPipeTest.php
@@ -169,11 +172,27 @@ public function testBigPipe() {
+    // The exception is expected. Do not interpret it as a test failure.
+    unlink(\Drupal::root() . '/' . $this->siteDirectory . '/error.log');

@@ -219,6 +243,19 @@ public function testBigPipeNoJs() {
+    // The exception is expected. Do not interpret it as a test failure.
+    unlink(\Drupal::root() . '/' . $this->siteDirectory . '/error.log');

Need to test that this is empty before simulating development otherwise throwing this away here might hide errors.

alexpott’s picture

Status: Needs work » Reviewed & tested by the community

Hmmm this is not the only test that does this (as pointed out by @Wim Leers on IRC)... I guess we just have to live with it atm... see \Drupal\system\Tests\Ajax\FormValuesTest for example. So back to rtbc for further committer review.

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 14: 2678568-14.patch, failed testing.

wim leers’s picture

Status: Needs work » Reviewed & tested by the community
StatusFileSize
new29.7 KB
catch’s picture

Status: Reviewed & tested by the community » Needs work
+++ b/core/modules/big_pipe/src/Render/BigPipe.php
@@ -238,7 +244,18 @@ protected function sendNoJsPlaceholders($html, $no_js_placeholders, AttachedAsse
       ];
-      $elements = $this->renderPlaceholder($placeholder, $placeholder_plus_cumulative_settings);
+      try {
+        $elements = $this->renderPlaceholder($placeholder, $placeholder_plus_cumulative_settings);
+      }
+      catch (\Exception $e) {
+        if (\Drupal::config('system.logging')->get('error_level') === ERROR_REPORTING_DISPLAY_VERBOSE) {
+          throw $e;
+        }
+        else {
+          continue;
+        }
+      }
+

This doesn't look right to me - it's eating the exception entirely when error verbose is off.

Could we either:

1. trigger_error() all the time, that'll go to the UI and/or the log, would also mean less logic since the error handler handles checking config etc.

2. trigger_error() in the else case if we think rethrowing the exception is important otherwise.

If we go for #2 I wonder if there needs to be some kind of helper for that.

wim leers’s picture

Status: Needs work » Needs review
StatusFileSize
new31.36 KB
new3.75 KB

Discussed with catch to get on the same page. Went with #2, because otherwise debugging is still significantly impaired, which itself already largely goes against what the issue title says.

Writing test coverage to verify that errors do in fact get logged was extremely painful, but I managed to do it.

fabianx’s picture

Status: Needs review » Reviewed & tested by the community

Back to RTBC, looks great to me.

catch’s picture

Status: Reviewed & tested by the community » Fixed

Committed/pushed to 8.2.x and cherry-picked to 8.1.x. Thanks!

  • catch committed eee3500 on 8.2.x
    Issue #2678568 by Wim Leers: Ensure good UX...
wim leers’s picture

Also committed & pushed to the contrib module for Drupal 8.0: http://drupalcode.org/project/big_pipe.git/commit/50e0fb6

alexpott’s picture

+++ b/core/modules/big_pipe/src/Render/BigPipe.php
@@ -238,7 +244,19 @@ protected function sendNoJsPlaceholders($html, $no_js_placeholders, AttachedAsse
+        if (\Drupal::config('system.logging')->get('error_level') === ERROR_REPORTING_DISPLAY_VERBOSE) {

@@ -263,7 +281,19 @@ protected function sendNoJsPlaceholders($html, $no_js_placeholders, AttachedAsse
+        if (\Drupal::config('system.logging')->get('error_level') === ERROR_REPORTING_DISPLAY_VERBOSE) {

@@ -320,7 +356,18 @@ protected function sendPlaceholders(array $placeholders, array $placeholder_orde
+        if (\Drupal::config('system.logging')->get('error_level') === ERROR_REPORTING_DISPLAY_VERBOSE) {

@@ -342,7 +389,18 @@ protected function sendPlaceholders(array $placeholders, array $placeholder_orde
+        if (\Drupal::config('system.logging')->get('error_level') === ERROR_REPORTING_DISPLAY_VERBOSE) {

How come we didn't inject the config service here? Should we open a follow-up to do this?

wim leers’s picture

#25: because this is for handling uncaught exceptions. i.e. when something fails: when code is broken.

Injecting this service means it's always initialized, and therefore always slows down this code. We only need that service in case of broken code, so there's no need for that service to be injected always.

alexpott’s picture

But the config factory will be initialised.

catch’s picture

To be honest my preference would be for trigger_error() here generally, then we don't have to copy what the error handler does, and don't have to inject anything or call out to \Drupal.

wim leers’s picture

But not rethrowing the exception will still mean it's painful to debug. The whole point of this issue is to ensure it's equally easy to debug with BigPipe as it is without.

Or am I missing something here?

catch’s picture

The trigger_error() will still show the exception in the UI during development, so it's not really much more painful than throwing the exception itself is it?

  • alexpott committed ce13a05 on 8.2.x
    Revert "Issue #2678568 by Wim Leers: Ensure good UX...
alexpott’s picture

Status: Fixed » Needs work

Unfortunately this patch introduced a PHP7 fail - probably due to the differences in error handling.

alexpott’s picture

wim leers’s picture

Status: Needs work » Needs review

The trigger_error() will still show the exception in the UI during development, so it's not really much more painful than throwing the exception itself is it?

No, that doesn't work, because:

  1. trigger_error() only allows for E_USER_* errors to be triggered
  2. _drupal_error_handler_real() treats all E_USER_* errors (except if thrown from a __toString() method) as non-fatal errors
  3. non-fatal errors are only displayed (even with verbose error logging) as messages
  4. … and it was already determined before rendering these placeholders that in fact no messages were to be displayed on the current HTML page

Therefore you will only get to see this trigger_error()-triggered error message on the next page you visit!

The consequence of doing #30 is therefore that the DX is worse than it is today in HEAD, and that only UX improves.

Thoughts/ideas?

dawehner’s picture

Thoughts/ideas?

At least this is logged by default as well, I don't see an issue though:

+        if (\Drupal::config('system.logging')->get('error_level') === ERROR_REPORTING_DISPLAY_VERBOSE) {

... this is the only sane configuration for people which can deal with that message.

wim leers’s picture

StatusFileSize
new4.04 KB

To be clear, this is what AFAICT @catch is asking for in #30, and I explained in #34 why that does not work.

wim leers’s picture

StatusFileSize
new31.5 KB
new1.27 KB

@dawehner in IRC agrees with me:

13:02:35 <WimLeers> dawehner: yes, but catch is arguing to NOT re-throw an exception, and just always use trigger_error()
13:02:49 <dawehner> oh I see, yeah I disagree with that
…
13:04:59 <dawehner> WimLeers: well, maybe catch is arguing for a better error handling
13:05:04 <WimLeers> I don't think so
13:05:31 <WimLeers> I think he just didn't realize the error handling system's use of drupal_set_message() and how that doesn't help in this situation
13:06:03 <dawehner> WimLeers: well, many systems convert any kind of errors to exceptions in development mode

I'm +100 for that, but that's a much bigger undertaking. I'd like to see BigPipe's DX fixed before Drupal 8.1.0 is released.


So, in light of #34–#36, I think the most sensible thing for me to do is to figure out why the patch in #20 that was committed and then reverted is failing for PHP7. This is the patch in #20, plus some debug output to figure that out. I suspect PHP7 simply logs things differently.

wim leers’s picture

Status: Needs review » Reviewed & tested by the community
StatusFileSize
new31.29 KB
new1.49 KB

So, #37 clearly shows the difference between PHP 5 and PHP 7. The failed assertionsare:

$this->assertTrue(FALSE !== strpos((string) unserialize($records[0]->variables)['@message'], "exception 'Exception' with message 'Oh noes!'"));
…
$this->assertTrue(FALSE !== strpos((string) unserialize($records[1]->variables)['@message'], "exception 'Exception' with message 'You are not allowed to say llamas are not cool!'"));

i.e. the expected strings are:

  1. exception 'Exception' with message 'Oh noes!'
  2. exception 'Exception' with message 'You are not allowed to say llamas are not cool!'

These expectations are met on PHP 5. But on PHP 7, the resulting strings are:

  1. Exception: Oh noes!
  2. Exception: You are not allowed to say llamas are not cool!

So, rather than asserting the presence of the exact entire error log string generated in PHP 5, we can just assert on the presence of the custom message. This then is still testing what we care about: that the actual expected exceptions are logged correctly. We don't care about the exact format that PHP 5 or 7 log them in.


The net difference between the patch here and #20 is then (and this is the entire interdiff):

-    $this->assertTrue(FALSE !== strpos((string) unserialize($records[0]->variables)['@message'], "exception 'Exception' with message 'Oh noes!'"));
+    $this->assertTrue(FALSE !== strpos((string) unserialize($records[0]->variables)['@message'], 'Oh noes!'));
     $this->assertEqual(RfcLogLevel::ERROR, $records[0]->severity);
-    $this->assertTrue(FALSE !== strpos((string) unserialize($records[1]->variables)['@message'], "exception 'Exception' with message 'You are not allowed to say llamas are not cool!'"));
+    $this->assertTrue(FALSE !== strpos((string) unserialize($records[1]->variables)['@message'], 'You are not allowed to say llamas are not cool!'));

That's it. And just for PHP 7 compatibility. I believe that makes it okay for me to re-RTBC this patch, since the changes are so utterly trivial.

fabianx’s picture

RTBC + 1

xjm’s picture

Issue tags: +rc target

@alexpott, @Cottser, @effulgentsia, and I agreed that this issue is valuable to add before 8.1.0 since it will affect the initial developer experience with BigPipe. Since it is an experimental module, the disruption from this change is still acceptable. Tagging as an RC target.

wim leers’s picture

the disruption from this change is still acceptable

To be more accurate, there is no disruption. It does not break anything. It does not change any APIs.

Also note that 80% of this patch is test coverage.

xjm’s picture

@Wim Leers, I guess I should have said "any potential for disruption", but it adds a new behavior for an exception being thrown/error being triggered. That type of change does add potential disruption in general (there were some really nasty criticals in D7 related to that kind of a change), and so for a stable module, we would at least be very cautious about committing it for a patch release. As an experimental module, Big Pipe is not subject to such restrictions, so it could go in during 8.1.x anyway, but better to get it in during RC for the initial developer experience with the module.

wim leers’s picture

+1 — thanks for all the detailed insight into your considerations!

alexpott’s picture

Status: Reviewed & tested by the community » Fixed

Still not super keen on not injecting this config, but I think it is better to proceed here as the improvements are tangible. I do think it is better to code for a day when \Drupal and the service location anti pattern is not possible.

Committed 653a363 and pushed to 8.1.x and 8.2.x. Thanks!

  • alexpott committed e53b13a on 8.2.x
    Issue #2678568 by Wim Leers: Ensure good UX...
wim leers’s picture

Fair enough. Thanks for committing it so that the improvements will definitely be available in 8.1.0. I filed #2702001: Inject config factory for BigPipe (including in exception handlers) to address that.

wim leers’s picture

Also committed & pushed to the contrib module for Drupal 8.0: http://drupalcode.org/project/big_pipe.git/commit/07ebd76

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.