Imbalanced AphrontWriteGuard: more beginUnguardedWrites() calls than endUnguardedWrites() calls
Open, HighPublic
Actions

Assigned To

None

Authored By

	Sten
	Apr 30 2024, 10:18

Description

Started to get the following Exception following the server's Centos RPMs being updated:

PHP message: [2024-04-30 09:23:46] EXCEPTION: (Exception) Imbalanced AphrontWriteGuard: more beginUnguardedWrites() calls than endUnguardedWrites() calls. at [<phorge>/src/aphront/writeguard/AphrontWriteGuard.php:99]
PHP message: arcanist(head=master, ref.master=ba42b63704b2, custom=4), phorge(head=master, ref.master=318d7a61feab)
PHP message:   #0 <#2> AphrontWriteGuard::dispose() called at [<phorge>/src/aphront/configuration/AphrontApplicationConfiguration.php:214]
PHP message:   #1 <#2> AphrontApplicationConfiguration::runHTTPRequest(AphrontPHPHTTPSink) called at [<phorge>/webroot/index.php:35]
PHP message:   #2 phlog(Exception) called at [<phorge>/src/aphront/response/AphrontUnhandledExceptionResponse.php:32]
PHP message:   #3 AphrontUnhandledExceptionResponse::setException(Exception) called at [<phorge>/webroot/index.php:46]

This exception would be triggered by running arc diff or arc branches

The fix is:

--- a/src/applications/conduit/controller/PhabricatorConduitAPIController.php
+++ b/src/applications/conduit/controller/PhabricatorConduitAPIController.php
@@ -76,7 +76,7 @@ final class PhabricatorConduitAPIController

       if ($auth_error === null) {
         if ($allow_unguarded_writes) {
-          $unguarded = AphrontWriteGuard::beginScopedUnguardedWrites();
+          AphrontWriteGuard::beginUnguardedWrites();
         }

         try {
@@ -92,8 +92,9 @@ final class PhabricatorConduitAPIController
             $error_info = $call->getErrorDescription($error_code);
           }
         }
+
         if ($allow_unguarded_writes) {
-          unset($unguarded);
+          AphrontWriteGuard::endUnguardedWrites();
         }
       } else {
         list($error_code, $error_info) = $auth_error;

Event Timeline

Sten created this task.Apr 30 2024, 10:18

Herald added subscribers: Cigaryno, Matthew, chris, tobiaswiese. · View Herald TranscriptApr 30 2024, 10:18

Sten updated the task description. (Show Details)Apr 30 2024, 10:19

Thanks. Premising that I cannot reproduce the issue. I use arc diff and arc branches frequently without issues 🤔 Tested both with and without authentication.

Also it's strange that the stack trace does not mention PhabricatorConduitAPIController

To find it, I needed to put in loads of debugging. It seems to be an issue with PHP deferring the execution of the object destructor until after the Imbalanced AphrontWriteGuard check, even though the object was unset prior to the check.

The issue occurs in Remi PHP 8.1.28, which is currently the latest 8.1 version

Had this issue occur elsewhere, so put a general 'fix' for it:

--- a/src/aphront/writeguard/AphrontWriteGuard.php
+++ b/src/aphront/writeguard/AphrontWriteGuard.php
@@ -96,12 +96,13 @@ final class AphrontWriteGuard extends Phobject {
     }

     if ($this->allowDepth > 0) {
-      throw new Exception(
+      phlog( new Exception(
         pht(
           'Imbalanced %s: more %s calls than %s calls.',
           __CLASS__,
           'beginUnguardedWrites()',
-          'endUnguardedWrites()'));
+          'endUnguardedWrites()'))
+      );
     }

Also starting to see other destructor related issues with Mediawiki, so this is almost certainly caused by PHP. Putting the 'fix' in here for anyone else who sees the error until PHP is updated!

I was not aware that we were executing critical business code inside __destruct() automagic calls. Wow!

https://we.phorge.it/source/phorge/browse/master/src/aphront/writeguard/AphrontScopedUnguardedWriteCapability.php

I agree with you if you think that the above approach is too much esoteric and creative.

So, if you see similar things:

$unguarded = AphrontWriteGuard::beginScopedUnguardedWrites();

// very interesting things

unset(unguarded)

You are very welcome in replacing that with something less esoteric, like:

// Make sure to end.
AphrontWriteGuard::beginUnguardedWrites();

try {

  // very interesting things

} finally {
  AphrontWriteGuard::endUnguardedWrites()
}

Or something similar.

Setting high priority since I'm scared :D Feel free to re-tune

aklapper subscribed.Jun 28 2024, 12:07

I've seen this occasionally when trying to log in via a /bin/auth recover link with same stacktrace as above, PHP 8.3.8 on a Fedora 40 machine:

Screenshot from 2024-06-28 14-08-29.png (383×927 px, 53 KB)

I do not understand if we have some race conditions, or, if the __destruct() is not properly called because of a bug in PHP 8.3.8, which is possible but unlikely

https://bugs.php.net/search.php?cmd=display&search_for=destructor+unset&direction=DESC&limit=30&status=Open&begin=30

Premising that I like the proposed patch, I think it's just a mitigation, and not a fix, since we probably have a race condition here.

	F2254728: Screenshot from 2024-06-28 14-08-29.png
	Jun 28 2024, 12:10

Imbalanced AphrontWriteGuard: more beginUnguardedWrites() calls than endUnguardedWrites() callsOpen, HighPublicActions

Description

Event Timeline

Imbalanced AphrontWriteGuard: more beginUnguardedWrites() calls than endUnguardedWrites() calls
Open, HighPublic
Actions