@@ -73,24 +73,36 @@ public function handle(CacheContext $context, callable $next) : PromiseInterface
7373 $ lock = $ this ->lock_factory ->createLock ($ lock_key , 30.0 );
7474
7575 if ($ lock ->acquire (false )) {
76- $ this ->logger ->debug ('AsyncCache LOCK_ACQUIRED: immediate ' , ['key ' => $ context ->key ]);
76+ $ this ->logger ->debug ('LOCK_ACQUIRED: Immediate acquisition successful ' , ['key ' => $ context ->key ]);
7777 $ this ->active_locks [$ lock_key ] = $ lock ;
7878
7979 return $ this ->handleWithLock ($ context , $ next , $ lock_key );
8080 }
8181
8282 if (null !== $ context ->stale_item ) {
83- $ now = (float ) $ context ->clock ->now ()->format ('U.u ' );
84- $ this ->dispatcher ?->dispatch(new CacheStatusEvent ($ context ->key , CacheStatus::Stale, $ now - $ context ->start_time , $ context ->options ->tags , $ now ));
85- $ this ->dispatcher ?->dispatch(new CacheHitEvent ($ context ->key , $ context ->stale_item ->data , $ now ));
83+ $ this ->logger ->debug ('LOCK_BUSY: Lock is busy, returning stale data immediately ' , ['key ' => $ context ->key ]);
84+
8685 /** @var T $stale_data */
8786 $ stale_data = $ context ->stale_item ->data ;
8887
8988 return \React \Promise \resolve ($ stale_data );
9089 }
9190
92- $ this ->logger ->debug ('AsyncCache LOCK_BUSY: waiting for lock asynchronously ' , ['key ' => $ context ->key ]);
91+ $ this ->logger ->debug ('LOCK_WAIT: Lock is busy and no stale data available, waiting asynchronously ' , ['key ' => $ context ->key ]);
92+
93+ return $ this ->waitForLock ($ context , $ next , $ lock_key );
94+ }
9395
96+ /**
97+ * @template T
98+ *
99+ * @param CacheContext $context
100+ * @param callable(CacheContext):PromiseInterface<T> $next
101+ * @param string $lock_key
102+ * @return PromiseInterface<T>
103+ */
104+ private function waitForLock (CacheContext $ context , callable $ next , string $ lock_key ) : PromiseInterface
105+ {
94106 $ start_time = (float ) $ context ->clock ->now ()->format ('U.u ' );
95107 $ timeout = 10.0 ;
96108 $ deferred = new Deferred ();
@@ -100,34 +112,35 @@ public function handle(CacheContext $context, callable $next) : PromiseInterface
100112 $ lock = $ this ->lock_factory ->createLock ($ lock_key , 30.0 );
101113
102114 if ($ lock ->acquire (false )) {
103- $ this ->logger ->debug ('AsyncCache LOCK_ACQUIRED: async ' , ['key ' => $ context ->key ]);
115+ $ this ->logger ->debug ('LOCK_ACQUIRED: Async acquisition successful after waiting ' , ['key ' => $ context ->key ]);
104116 $ this ->active_locks [$ lock_key ] = $ lock ;
105117
118+ // Double-check cache after acquiring lock (someone else might have populated it)
106119 $ this ->storage ->get ($ context ->key , $ context ->options )->then (
107- function ($ cached_item ) use ($ context , $ next , $ lock_key, $ start_time , $ deferred ) {
108- $ now = ( float ) $ context ->clock ->now ()->format ( ' U.u ' );
109- if ($ cached_item instanceof CachedItem && $ cached_item ->isFresh (( int ) $ now )) {
110- $ this ->dispatcher ?->dispatch( new CacheStatusEvent ( $ context -> key , CacheStatus::Hit, $ now - $ start_time , $ context ->options -> tags , $ now ) );
120+ function ($ item ) use ($ context , $ next , $ lock_key , $ deferred ) {
121+ $ now_ts = $ context ->clock ->now ()->getTimestamp ( );
122+ if ($ item instanceof CachedItem && $ item ->isFresh ($ now_ts )) {
123+ $ this ->logger -> debug ( ' LOCK_DOUBLE_CHECK: Item is fresh after lock acquisition, skipping fetch ' , [ ' key ' => $ context ->key ] );
111124 $ this ->releaseLock ($ lock_key );
112- $ deferred ->resolve ($ cached_item ->data );
125+ $ deferred ->resolve ($ item ->data );
113126
114127 return ;
115128 }
116129
117- /** @var PromiseInterface<T> $inner_promise */
118- $ inner_promise = $ this ->handleWithLock ($ context , $ next , $ lock_key );
119- $ inner_promise ->then (
120- fn ($ v ) => $ deferred ->resolve ($ v )
121- )->catch (function (\Throwable $ e ) use ($ deferred ) {
122- $ this ->logger ->error ('AsyncCache LOCK_INNER_ERROR: {msg} ' , ['msg ' => $ e ->getMessage ()]);
123- $ deferred ->reject ($ e );
124- });
130+ $ this ->handleWithLock ($ context , $ next , $ lock_key )->then (
131+ fn ($ v ) => $ deferred ->resolve ($ v ),
132+ function ($ e ) use ($ deferred ) {
133+ $ this ->logger ->error ('LOCK_INNER_ERROR: Fetch failed after lock acquisition ' , ['error ' => $ e ->getMessage ()]);
134+ $ deferred ->reject ($ e );
135+ }
136+ );
137+ },
138+ function ($ e ) use ($ lock_key , $ deferred ) {
139+ $ this ->logger ->error ('LOCK_STORAGE_ERROR: Cache check failed after lock acquisition ' , ['error ' => $ e ->getMessage ()]);
140+ $ this ->releaseLock ($ lock_key );
141+ $ deferred ->reject ($ e );
125142 }
126- )->catch (function (\Throwable $ e ) use ($ context , $ lock_key , $ deferred ) {
127- $ this ->logger ->error ('AsyncCache LOCK_STORAGE_ERROR: {msg} ' , ['key ' => $ context ->key , 'msg ' => $ e ->getMessage ()]);
128- $ this ->releaseLock ($ lock_key );
129- $ deferred ->reject ($ e );
130- });
143+ );
131144
132145 return ;
133146 }
@@ -138,25 +151,18 @@ function ($cached_item) use ($context, $next, $lock_key, $start_time, $deferred)
138151 return ;
139152 }
140153
141- // Retry after delay
142154 \React \Promise \Timer \resolve (0.05 )->then (function () use ($ attempt ) {
143155 $ attempt ();
144156 });
145157 } catch (\Throwable $ e ) {
146- $ this ->logger ->error ('AsyncCache LOCK_RETRY_ERROR: {msg} ' , ['msg ' => $ e ->getMessage ()]);
158+ $ this ->logger ->error ('LOCK_RETRY_ERROR: Lock acquisition attempt failed ' , ['error ' => $ e ->getMessage ()]);
147159 $ deferred ->reject ($ e );
148160 }
149161 };
150162
151163 $ attempt ();
152164
153- /** @var PromiseInterface<T> $promise */
154- $ promise = $ deferred ->promise ();
155- $ promise ->catch (function (\Throwable $ e ) use ($ context ) {
156- $ this ->logger ->debug ('AsyncCache LOCK_PIPELINE_ERROR: {msg} ' , ['key ' => $ context ->key , 'msg ' => $ e ->getMessage ()]);
157- });
158-
159- return $ promise ;
165+ return $ deferred ->promise ();
160166 }
161167
162168 /**
0 commit comments