From 9f349d299662cc4950ef257c90189ef0afd5474b Mon Sep 17 00:00:00 2001 From: Torben Dannhauer Date: Thu, 2 Jul 2026 09:18:50 +0200 Subject: [PATCH] fix(activesync): treat collection lock contention as transient during PING A PING polling loop that hit a collection lock held by a parallel SYNC received a generic Horde_ActiveSync_Exception and reacted with the corrupt-state recovery path: a device state reset via loadState() with an empty collection array. This caused "Undefined array key" warnings in State/Base.php, and the reset itself failed again on the still-held lock, escaping as an uncaught exception and returning HTTP 500 to the client. In the worst case the recovery would wipe healthy sync state just because another request momentarily held the lock. Throw Horde_ActiveSync_Exception_TemporaryFailure on lock contention in the Sql and Mongo state drivers, and catch it in pollForChanges() to skip the affected collection until the next poll iteration instead of resetting state. Defer the StaleState recovery resets the same way when the lock is unavailable. Guard the folder object creation in loadState() against an empty collection array to silence the PHP 8 warnings on legitimate resets. --- lib/Horde/ActiveSync/Collections.php | 63 ++++++++++--- lib/Horde/ActiveSync/State/Base.php | 15 ++- lib/Horde/ActiveSync/State/Mongo.php | 4 +- lib/Horde/ActiveSync/State/Sql.php | 5 +- .../PingCollectionLockContentionTest.php | 93 +++++++++++++++++++ .../StateTest/Sql/CollectionLockTest.php | 67 +++++++++++++ 6 files changed, 229 insertions(+), 18 deletions(-) create mode 100644 test/unit/Horde/ActiveSync/PingCollectionLockContentionTest.php diff --git a/lib/Horde/ActiveSync/Collections.php b/lib/Horde/ActiveSync/Collections.php index f6666080..10b6dfb7 100644 --- a/lib/Horde/ActiveSync/Collections.php +++ b/lib/Horde/ActiveSync/Collections.php @@ -1337,12 +1337,25 @@ public function pollForChanges($heartbeat, $interval, array $options = []) $e->getMessage() ) ); - $this->_as->state->loadState( - [], - null, - Horde_ActiveSync::REQUEST_TYPE_SYNC, - $id - ); + try { + $this->_as->state->loadState( + [], + null, + Horde_ActiveSync::REQUEST_TYPE_SYNC, + $id + ); + } catch (Horde_ActiveSync_Exception_TemporaryFailure $e) { + // Reset blocked by a parallel request holding the + // collection lock. Retry on the next poll iteration. + $this->_logger->notice( + sprintf( + 'COLLECTIONS: State reset for %s deferred: %s', + $id, + $e->getMessage() + ) + ); + continue; + } $this->setGetChangesFlag($id); $dataavailable = true; continue; @@ -1394,6 +1407,19 @@ public function pollForChanges($heartbeat, $interval, array $options = []) } catch (Horde_ActiveSync_Exception_FolderGone $e) { $this->_logger->warn('COLLECTIONS: Folder gone for collection ' . $collection['id']); return self::COLLECTION_ERR_FOLDERSYNC_REQUIRED; + } catch (Horde_ActiveSync_Exception_TemporaryFailure $e) { + // Transient contention (e.g. collection lock held by a + // parallel SYNC). Skip this collection for now; it will + // be retried on the next poll iteration. Do NOT reset + // state for a transient condition. + $this->_logger->notice( + sprintf( + 'COLLECTIONS: Temporary failure loading state for %s; retrying next iteration: %s', + $id, + $e->getMessage() + ) + ); + continue; } catch (Horde_ActiveSync_Exception $e) { $this->_logger->err('COLLECTIONS: Error loading state: ' . $e->getMessage()); $this->_as->state->loadState( @@ -1437,12 +1463,25 @@ public function pollForChanges($heartbeat, $interval, array $options = []) $e->getMessage() ) ); - $this->_as->state->loadState( - [], - null, - Horde_ActiveSync::REQUEST_TYPE_SYNC, - $id - ); + try { + $this->_as->state->loadState( + [], + null, + Horde_ActiveSync::REQUEST_TYPE_SYNC, + $id + ); + } catch (Horde_ActiveSync_Exception_TemporaryFailure $e) { + // Reset blocked by a parallel request holding the + // collection lock. Retry on the next poll iteration. + $this->_logger->notice( + sprintf( + 'COLLECTIONS: State reset for %s deferred: %s', + $id, + $e->getMessage() + ) + ); + continue; + } $this->setGetChangesFlag($id); $dataavailable = true; } catch (Horde_ActiveSync_Exception_FolderGone $e) { diff --git a/lib/Horde/ActiveSync/State/Base.php b/lib/Horde/ActiveSync/State/Base.php index c05dd935..5aa1e99a 100644 --- a/lib/Horde/ActiveSync/State/Base.php +++ b/lib/Horde/ActiveSync/State/Base.php @@ -1115,10 +1115,17 @@ public function loadState(array $collection, $syncKey, $type = null, $id = null) if ($type == Horde_ActiveSync::REQUEST_TYPE_FOLDERSYNC) { $this->_folder = []; } else { - // Create a new folder object. - $this->_folder = ($this->_collection['class'] == Horde_ActiveSync::CLASS_EMAIL) - ? new Horde_ActiveSync_Folder_Imap($this->_collection['serverid'], Horde_ActiveSync::CLASS_EMAIL) - : ($this->_collection['serverid'] == 'RI' ? new Horde_ActiveSync_Folder_RI('RI', 'RI') : new Horde_ActiveSync_Folder_Collection($this->_collection['serverid'], $this->_collection['class'])); + // Create a new folder object. The collection array may be + // empty when resetting state during error recovery. + $class = $this->_collection['class'] ?? null; + $serverid = $this->_collection['serverid'] ?? null; + if ($class == Horde_ActiveSync::CLASS_EMAIL) { + $this->_folder = new Horde_ActiveSync_Folder_Imap($serverid, Horde_ActiveSync::CLASS_EMAIL); + } elseif ($serverid == 'RI') { + $this->_folder = new Horde_ActiveSync_Folder_RI('RI', 'RI'); + } else { + $this->_folder = new Horde_ActiveSync_Folder_Collection($serverid, $class); + } } $this->_syncKey = '0'; $lockFolderId = ($type == Horde_ActiveSync::REQUEST_TYPE_FOLDERSYNC) diff --git a/lib/Horde/ActiveSync/State/Mongo.php b/lib/Horde/ActiveSync/State/Mongo.php index 101c7de0..90bfda10 100644 --- a/lib/Horde/ActiveSync/State/Mongo.php +++ b/lib/Horde/ActiveSync/State/Mongo.php @@ -550,7 +550,9 @@ protected function _acquireCollectionLock($folderId = null) } } - throw new Horde_ActiveSync_Exception('Could not acquire collection lock.'); + // Contention with a parallel request is a transient condition, not + // corrupt state - callers must not react with a state reset. + throw new Horde_ActiveSync_Exception_TemporaryFailure('Could not acquire collection lock.'); } /** diff --git a/lib/Horde/ActiveSync/State/Sql.php b/lib/Horde/ActiveSync/State/Sql.php index f780a549..2c639671 100644 --- a/lib/Horde/ActiveSync/State/Sql.php +++ b/lib/Horde/ActiveSync/State/Sql.php @@ -430,7 +430,10 @@ protected function _acquireCollectionLock($folderId = null) if ($started) { $this->_db->rollbackDbTransaction(); } - throw new Horde_ActiveSync_Exception('Collection lock held.'); + // Contention with a parallel request is a transient + // condition, not corrupt state - callers must not react + // with a state reset. + throw new Horde_ActiveSync_Exception_TemporaryFailure('Collection lock held.'); } $token = random_int(1, PHP_INT_MAX); diff --git a/test/unit/Horde/ActiveSync/PingCollectionLockContentionTest.php b/test/unit/Horde/ActiveSync/PingCollectionLockContentionTest.php new file mode 100644 index 00000000..6448cc78 --- /dev/null +++ b/test/unit/Horde/ActiveSync/PingCollectionLockContentionTest.php @@ -0,0 +1,93 @@ + + * @license http://www.horde.org/licenses/gpl GPLv2 + * @copyright 2026 The Horde Project + * @package ActiveSync + */ + +namespace Horde\ActiveSync; + +use Horde_ActiveSync; +use Horde_ActiveSync_Collections; +use Horde_ActiveSync_Exception_TemporaryFailure; +use Horde_ActiveSync_Log_Logger; +use Horde_ActiveSync_SyncCache; +use Horde_Log_Handler_Null; +use PHPUnit\Framework\Attributes\CoversClass; +use PHPUnit\Framework\TestCase; +use ReflectionProperty; + +#[CoversClass(Horde_ActiveSync_Collections::class)] +class PingCollectionLockContentionTest extends TestCase +{ + private const COLLECTION_ID = 'F1234abcd'; + + /** + * A collection lock held by a parallel SYNC must not trigger a state + * reset; the collection is skipped and retried on the next iteration. + */ + public function testPollForChangesSkipsCollectionOnLockContention() + { + $state = $this->createMock('Horde_ActiveSync_State_Sql'); + $state->method('getSyncCache')->willReturn(['timestamp' => 0]); + $state->expects($this->never())->method('loadState'); + + $cache = new Horde_ActiveSync_SyncCache($state, 'device', 'user'); + + $as = $this->createMock(Horde_ActiveSync::class); + $as->logger = new Horde_ActiveSync_Log_Logger(new Horde_Log_Handler_Null()); + $as->state = $state; + $as->device = (object) [ + 'id' => 'device', + 'version' => Horde_ActiveSync::VERSION_FOURTEEN, + ]; + $as->provisioning = Horde_ActiveSync::PROVISIONING_NONE; + + $collections = $this->getMockBuilder(Horde_ActiveSync_Collections::class) + ->setConstructorArgs([$cache, $as]) + ->onlyMethods([ + 'initCollectionState', + 'updateCollectionsFromCache', + 'checkStaleRequest', + 'collectionsNeedFolderResync', + 'restorePingableCollectionsFromCache', + 'havePingableCollections', + 'haveHierarchy', + 'save', + 'setGetChangesFlag', + '_sleep', + ]) + ->getMock(); + + $collections->method('collectionsNeedFolderResync')->willReturn(false); + $collections->method('havePingableCollections')->willReturn(true); + $collections->method('haveHierarchy')->willReturn(true); + $collections->method('checkStaleRequest')->willReturn(false); + $collections->method('initCollectionState')->willThrowException( + new Horde_ActiveSync_Exception_TemporaryFailure('Collection lock held.') + ); + $collections->expects($this->never())->method('setGetChangesFlag'); + + $property = new ReflectionProperty(Horde_ActiveSync_Collections::class, '_collections'); + $property->setAccessible(true); + $property->setValue($collections, [ + self::COLLECTION_ID => [ + 'id' => self::COLLECTION_ID, + 'synckey' => '{6a13541c-a3bc-448b-853c-915b00000000}14', + 'class' => Horde_ActiveSync::CLASS_EMAIL, + 'serverid' => 'INBOX', + ], + ]); + + $this->assertFalse( + $collections->pollForChanges(1, 1, ['pingable' => true]) + ); + } +} diff --git a/test/unit/Horde/ActiveSync/StateTest/Sql/CollectionLockTest.php b/test/unit/Horde/ActiveSync/StateTest/Sql/CollectionLockTest.php index b0aa83f6..54275f65 100644 --- a/test/unit/Horde/ActiveSync/StateTest/Sql/CollectionLockTest.php +++ b/test/unit/Horde/ActiveSync/StateTest/Sql/CollectionLockTest.php @@ -15,6 +15,8 @@ use Horde\ActiveSync\Test\Helpers\DbHelper; use PHPUnit\Framework\TestCase; use Horde_ActiveSync; +use Horde_ActiveSync_Exception_TemporaryFailure; +use Horde_ActiveSync_Folder_Collection; use Horde_ActiveSync_State_Sql; use Horde_ActiveSync_Folder_Imap; use Horde_ActiveSync_Log_Logger; @@ -22,6 +24,15 @@ use Horde_Log_Handler_Null; use ReflectionClass; +/** + * tables() is provided by the schema object via __call() on real adapters, + * so it must be declared explicitly for mocking. + */ +interface DbAdapterWithTables extends \Horde_Db_Adapter +{ + public function tables(); +} + class CollectionLockTest extends TestCase { public function testAcquireAndReleaseCollectionLockOnSqlite() @@ -84,6 +95,62 @@ public function testSaveCommitsCollectionLockTransaction() $this->assertFalse($this->_getProperty($state, '_stateRowLockHeld')); } + public function testHeldLockThrowsTemporaryFailure() + { + $db = $this->createMock(DbAdapterWithTables::class); + $db->method('tables')->willReturn(['horde_activesync_collection_lock']); + $db->method('transactionStarted')->willReturn(false); + $db->method('selectValue')->willReturn(1); + $db->method('selectOne')->willReturn([ + 'lock_token' => 42, + 'lock_time' => time(), + ]); + $db->expects($this->atLeastOnce())->method('rollbackDbTransaction'); + + $state = $this->_newState($db); + $this->_setProperty($state, '_type', Horde_ActiveSync::REQUEST_TYPE_SYNC); + $this->_setProperty($state, '_collection', ['id' => 'Ftest']); + + $this->expectException(Horde_ActiveSync_Exception_TemporaryFailure::class); + $this->_method($state, '_acquireCollectionLock')->invoke($state); + } + + public function testLoadStateResetWithEmptyCollectionEmitsNoWarnings() + { + if (!extension_loaded('pdo_sqlite')) { + $this->markTestSkipped('PDO SQLite extension is not loaded'); + } + + $migrationDir = dirname(__DIR__, 6) . '/migration/Horde/ActiveSync'; + $db = DbHelper::createSqliteDb([ + 'migrations' => [[ + 'migrationsPath' => $migrationDir, + 'schemaTableName' => 'horde_activesync_schema_info', + ]], + ]); + + $state = $this->_newState($db); + + $warnings = []; + set_error_handler(function ($errno, $errstr) use (&$warnings) { + $warnings[] = $errstr; + return true; + }, E_WARNING | E_NOTICE); + try { + // Error-recovery resets pass an empty collection array. + $state->loadState([], null, Horde_ActiveSync::REQUEST_TYPE_SYNC, 'Ftest'); + } finally { + restore_error_handler(); + } + + $this->assertSame([], $warnings); + $this->assertInstanceOf( + Horde_ActiveSync_Folder_Collection::class, + $this->_getProperty($state, '_folder') + ); + $this->assertFalse($this->_getProperty($state, '_collectionLockHeld')); + } + public function testSkipsCollectionLockWhenTableMissing() { if (!extension_loaded('pdo_sqlite')) {