Skip to content

Commit ea5b7b1

Browse files
chubes4chubes4
authored
fix: include lock owner diagnostics on busy workspace errors (#478)
1 parent f4a6d43 commit ea5b7b1

4 files changed

Lines changed: 236 additions & 22 deletions

File tree

‎inc/Cli/Commands/WorkspaceCommand.php‎

Lines changed: 32 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -133,7 +133,7 @@ public function list_repos( array $args, array $assoc_args ): void {
133133
$result = $ability->execute($input);
134134

135135
if ( is_wp_error($result) ) {
136-
WP_CLI::error($result->get_error_message());
136+
$this->render_workspace_error($result);
137137
return;
138138
}
139139

@@ -2758,6 +2758,37 @@ function ( $wt ) {
27582758
}
27592759
}
27602760

2761+
private function render_workspace_error( \WP_Error $error ): void {
2762+
$data = (array) $error->get_error_data();
2763+
if ( 'workspace_repo_busy' !== $error->get_error_code() ) {
2764+
WP_CLI::error($error->get_error_message());
2765+
return;
2766+
}
2767+
2768+
$lock = is_array($data['active_lock'] ?? null) ? (array) $data['active_lock'] : array();
2769+
if ( ! empty($lock) ) {
2770+
WP_CLI::warning(sprintf('Lock owner: %s', (string) ( $lock['owner'] ?? 'unknown' )));
2771+
WP_CLI::log(sprintf('Lock key: %s', (string) ( $lock['lock_key'] ?? $data['lock_key'] ?? '-' )));
2772+
WP_CLI::log(sprintf('Scope: %s', (string) ( $lock['scope'] ?? $data['scope'] ?? $data['repo'] ?? '-' )));
2773+
WP_CLI::log(sprintf('Path: %s', (string) ( $lock['metadata']['lock_path'] ?? $data['lock_path'] ?? '-' )));
2774+
WP_CLI::log(sprintf('Acquired: %s', (string) ( $lock['acquired_at'] ?? '-' )));
2775+
WP_CLI::log(sprintf('Heartbeat: %s', (string) ( $lock['heartbeat_at'] ?? '-' )));
2776+
WP_CLI::log(sprintf('Expires: %s', (string) ( $lock['expires_at'] ?? '-' )));
2777+
if ( isset($lock['age_seconds']) || isset($lock['retry_after_seconds']) ) {
2778+
WP_CLI::log(sprintf('Age/retry: %ss old; retry after up to %ss', (string) ( $lock['age_seconds'] ?? '-' ), (string) ( $lock['retry_after_seconds'] ?? '-' )));
2779+
}
2780+
$owner_context = (array) ( $lock['metadata']['owner_context'] ?? array() );
2781+
if ( ! empty($owner_context['wp_cli_args']) ) {
2782+
WP_CLI::log(sprintf('Command: %s', (string) $owner_context['wp_cli_args']));
2783+
}
2784+
if ( ! empty($owner_context['kimaki_session_id']) || ! empty($owner_context['opencode_session_id']) ) {
2785+
WP_CLI::log(sprintf('Session: %s', (string) ( $owner_context['kimaki_session_id'] ?? $owner_context['opencode_session_id'] ?? '' )));
2786+
}
2787+
}
2788+
2789+
WP_CLI::error($error->get_error_message());
2790+
}
2791+
27612792
/**
27622793
* Render workspace hygiene report output.
27632794
*

‎inc/Workspace/WorkspaceLockStore.php‎

Lines changed: 110 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -147,6 +147,65 @@ public static function status(): array {
147147
// phpcs:enable WordPress.DB.PreparedSQL.InterpolatedNotPrepared
148148
}
149149

150+
/**
151+
* Return the active DB-visible lock row for a specific lock target.
152+
*
153+
* @return array<string,mixed>|null|\WP_Error
154+
*/
155+
public static function active_lock( string $lock_key, string $scope ): array|null|\WP_Error {
156+
if ( ! self::is_available() ) {
157+
return null;
158+
}
159+
160+
$ensured = self::ensure_table();
161+
if ( $ensured instanceof \WP_Error ) {
162+
return $ensured;
163+
}
164+
165+
global $wpdb;
166+
$table = self::table_name();
167+
$now = gmdate('Y-m-d H:i:s');
168+
169+
// phpcs:disable WordPress.DB.PreparedSQL.InterpolatedNotPrepared -- Table name from $wpdb->prefix, not user input.
170+
$row = $wpdb->get_row(
171+
$wpdb->prepare(
172+
"SELECT id, lock_key, purpose, scope, owner, run_id, job_id, status, acquired_at, heartbeat_at, expires_at, released_at, metadata_json FROM {$table} WHERE lock_key = %s AND scope = %s AND status = %s AND expires_at >= %s ORDER BY acquired_at DESC, id DESC LIMIT 1",
173+
$lock_key,
174+
$scope,
175+
'active',
176+
$now
177+
),
178+
ARRAY_A
179+
);
180+
// phpcs:enable WordPress.DB.PreparedSQL.InterpolatedNotPrepared
181+
182+
if ( empty($row) || ! is_array($row) ) {
183+
return null;
184+
}
185+
186+
$row['id'] = (int) ( $row['id'] ?? 0 );
187+
$row['job_id'] = isset($row['job_id']) ? (int) $row['job_id'] : null;
188+
$row['metadata'] = self::decode_metadata( (string) ( $row['metadata_json'] ?? '' ) );
189+
unset($row['metadata_json']);
190+
191+
$acquired = self::timestamp_seconds( (string) ( $row['acquired_at'] ?? '' ) );
192+
$heartbeat = self::timestamp_seconds( (string) ( $row['heartbeat_at'] ?? '' ) );
193+
$expires = self::timestamp_seconds( (string) ( $row['expires_at'] ?? '' ) );
194+
$time = time();
195+
if ( null !== $acquired ) {
196+
$row['age_seconds'] = max(0, $time - $acquired);
197+
}
198+
if ( null !== $heartbeat ) {
199+
$row['heartbeat_age_seconds'] = max(0, $time - $heartbeat);
200+
}
201+
if ( null !== $expires ) {
202+
$row['expires_in_seconds'] = max(0, $expires - $time);
203+
$row['retry_after_seconds'] = max(0, $expires - $time);
204+
}
205+
206+
return $row;
207+
}
208+
150209
/**
151210
* Prune expired DB lock rows according to retention policy.
152211
*
@@ -279,9 +338,37 @@ private static function released_ttl_seconds(): int {
279338
return max(3600, $seconds);
280339
}
281340

341+
public static function default_owner_context(): array {
342+
$context = array(
343+
'host' => function_exists('gethostname') ? (string) gethostname() : 'unknown-host',
344+
'pid' => function_exists('getmypid') ? (string) getmypid() : 'unknown-pid',
345+
);
346+
$env_map = array(
347+
'kimaki_session_id' => 'KIMAKI_SESSION_ID',
348+
'opencode_session_id' => 'OPENCODE_SESSION_ID',
349+
'datamachine_task_url' => 'DATAMACHINE_TASK_URL',
350+
'datamachine_task_ref' => 'DATAMACHINE_TASK_REF',
351+
'datamachine_agent' => 'DATAMACHINE_AGENT',
352+
'datamachine_agent_name' => 'DATAMACHINE_AGENT_NAME',
353+
);
354+
foreach ( $env_map as $key => $env ) {
355+
$value = getenv($env);
356+
if ( false !== $value && '' !== trim( (string) $value) ) {
357+
$context[ $key ] = self::bounded_string( (string) $value, 300);
358+
}
359+
}
360+
361+
if ( isset($_SERVER['argv']) && is_array($_SERVER['argv']) ) {
362+
$context['wp_cli_args'] = self::bounded_string(self::redact_secret_values(implode(' ', array_map('strval', $_SERVER['argv']))), 1000);
363+
}
364+
365+
return $context;
366+
}
367+
282368
private static function default_owner(): string {
283-
$host = function_exists('gethostname') ? (string) gethostname() : 'unknown-host';
284-
$pid = function_exists('getmypid') ? (string) getmypid() : 'unknown-pid';
369+
$context = self::default_owner_context();
370+
$host = (string) ( $context['host'] ?? 'unknown-host' );
371+
$pid = function_exists('getmypid') ? (string) getmypid() : 'unknown-pid';
285372
return $host . ':' . $pid;
286373
}
287374

@@ -309,4 +396,25 @@ private static function encode_metadata( array $metadata ): string {
309396
$json = false === $json ? '{}' : (string) $json;
310397
return substr($json, 0, 8192);
311398
}
399+
400+
/**
401+
* @return array<string,mixed>
402+
*/
403+
private static function decode_metadata( string $json ): array {
404+
$decoded = json_decode($json, true);
405+
return is_array($decoded) ? $decoded : array();
406+
}
407+
408+
private static function timestamp_seconds( string $timestamp ): ?int {
409+
if ( '' === trim($timestamp) ) {
410+
return null;
411+
}
412+
413+
$seconds = strtotime($timestamp . ' UTC');
414+
return false === $seconds ? null : (int) $seconds;
415+
}
416+
417+
private static function redact_secret_values( string $value ): string {
418+
return (string) preg_replace('/(--(?:password|token|key|secret|authorization)(?:=|\s+))\S+/i', '$1[redacted]', $value);
419+
}
312420
}

‎inc/Workspace/WorkspaceMutationLock.php‎

Lines changed: 37 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -122,6 +122,7 @@ public static function acquire( string $workspace_path, string $repo, int $timeo
122122
'metadata' => array(
123123
'workspace_path' => $workspace_path,
124124
'lock_path' => $lock_path,
125+
'owner_context' => WorkspaceLockStore::default_owner_context(),
125126
),
126127
)
127128
);
@@ -142,12 +143,7 @@ public static function acquire( string $workspace_path, string $repo, int $timeo
142143
'Workspace repo "%s" is busy with another worktree lifecycle mutation. Retry after the current add/remove/cleanup/prune operation completes.',
143144
$repo
144145
),
145-
array(
146-
'status' => 423,
147-
'retryable' => true,
148-
'repo' => $repo,
149-
'lock_path' => $lock_path,
150-
)
146+
self::busy_error_data($repo, $lock_path)
151147
);
152148
}
153149

@@ -257,15 +253,45 @@ private static function lock_status_keys( array $status, string $state ): array
257253
);
258254
}
259255

256+
/**
257+
* @return array<string,mixed>
258+
*/
259+
private static function busy_error_data( string $repo, string $lock_path ): array {
260+
$lock_key = 'worktree-' . $repo;
261+
$data = array(
262+
'status' => 423,
263+
'retryable' => true,
264+
'repo' => $repo,
265+
'scope' => $repo,
266+
'lock_key' => $lock_key,
267+
'lock_path' => $lock_path,
268+
);
269+
270+
$active_lock = WorkspaceLockStore::active_lock($lock_key, $repo);
271+
if ( is_array($active_lock) ) {
272+
$data['active_lock'] = $active_lock;
273+
if ( isset($active_lock['retry_after_seconds']) ) {
274+
$data['retry_after_seconds'] = (int) $active_lock['retry_after_seconds'];
275+
}
276+
if ( isset($active_lock['age_seconds']) ) {
277+
$data['age_seconds'] = (int) $active_lock['age_seconds'];
278+
}
279+
} elseif ( is_wp_error($active_lock) ) {
280+
$data['lock_store_error'] = $active_lock->get_error_message();
281+
}
282+
283+
return $data;
284+
}
285+
260286
/**
261287
* @return array<string,mixed>
262288
*/
263289
private static function filesystem_status( string $workspace_path ): array {
264-
$lock_dir = rtrim($workspace_path, '/') . '/.locks';
265-
$files = is_dir($lock_dir) ? glob($lock_dir . '/*.lock') : array();
266-
$files = false === $files ? array() : $files;
267-
$policy = self::retention_policy();
268-
$cutoff = time() - (int) $policy['filesystem_stale_after_seconds'];
290+
$lock_dir = rtrim($workspace_path, '/') . '/.locks';
291+
$files = is_dir($lock_dir) ? glob($lock_dir . '/*.lock') : array();
292+
$files = false === $files ? array() : $files;
293+
$policy = self::retention_policy();
294+
$cutoff = time() - (int) $policy['filesystem_stale_after_seconds'];
269295
$active = 0;
270296
$stale = 0;
271297
$recent = 0;

‎tests/smoke-workspace-mutation-lock.php‎

Lines changed: 57 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,10 @@ function wp_mkdir_p( string $path ): bool
5858
}
5959
}
6060

61+
if (! defined('ARRAY_A') ) {
62+
define('ARRAY_A', 'ARRAY_A');
63+
}
64+
6165
if (! function_exists('wp_json_encode') ) {
6266
function wp_json_encode( $data, int $flags = 0 )
6367
{
@@ -118,6 +122,21 @@ public function get_col( string $sql ): array
118122
return array_values(array_unique(array_filter($keys)));
119123
}
120124

125+
/**
126+
* @return array<string,mixed>|null
127+
*/
128+
public function get_row( string $sql, string $output ): ?array // phpcs:ignore Generic.CodeAnalysis.UnusedFunctionParameter.FoundAfterLastUsed
129+
{
130+
$rows = $this->matching_rows($sql);
131+
return empty($rows) ? null : $rows[count($rows) - 1];
132+
}
133+
134+
public function query( string $sql ): int // phpcs:ignore Generic.CodeAnalysis.UnusedFunctionParameter.FoundAfterLastUsed
135+
{
136+
$this->rows_affected = 0;
137+
return 0;
138+
}
139+
121140
public function prepare( string $query, mixed ...$args ): string
122141
{
123142
foreach ( $args as $arg ) {
@@ -158,6 +177,8 @@ static function ( array $row ) use ( $sql, $now ): bool {
158177
}
159178
}
160179

180+
class DataMachineCode_Fake_WPDB extends Workspace_Mutation_Lock_Test_Wpdb {}
181+
161182
include __DIR__ . '/../inc/Workspace/WorkspaceLockStore.php';
162183
include __DIR__ . '/../inc/Workspace/WorkspaceMutationLock.php';
163184

@@ -195,10 +216,11 @@ function () use ( $tmp ) {
195216
$assert(1, (int) $status['active'], 'held filesystem lock is visible in aggregate active count');
196217
$assert(false, (bool) $status['database']['available'], 'DB lock store reports unavailable in pure-PHP smoke context');
197218

198-
$busy = \DataMachineCode\Workspace\WorkspaceMutationLock::acquire($tmp, 'demo', 0);
199-
$assert(true, is_wp_error($busy), 'same repo acquisition fails fast while held');
200-
$assert('workspace_repo_busy', is_wp_error($busy) ? $busy->get_error_code() : '', 'busy failure uses DMC-shaped retryable code');
201-
$assert(true, is_wp_error($busy) ? (bool) ( $busy->get_error_data()['retryable'] ?? false ) : false, 'busy failure is marked retryable');
219+
$busy = \DataMachineCode\Workspace\WorkspaceMutationLock::acquire($tmp, 'demo', 0);
220+
$assert(true, is_wp_error($busy), 'same repo acquisition fails fast while held');
221+
$assert('workspace_repo_busy', is_wp_error($busy) ? $busy->get_error_code() : '', 'busy failure uses DMC-shaped retryable code');
222+
$assert(true, is_wp_error($busy) ? (bool) ( $busy->get_error_data()['retryable'] ?? false ) : false, 'busy failure is marked retryable');
223+
$assert('worktree-demo', is_wp_error($busy) ? (string) ( $busy->get_error_data()['lock_key'] ?? '' ) : '', 'busy failure includes lock key');
202224

203225
$other = \DataMachineCode\Workspace\WorkspaceMutationLock::acquire($tmp, 'other', 0);
204226
$assert(false, is_wp_error($other), 'different repo acquisition is independent');
@@ -272,10 +294,37 @@ function () {
272294

273295
$post_exception = \DataMachineCode\Workspace\WorkspaceMutationLock::acquire($tmp, 'demo', 0);
274296
$assert(false, is_wp_error($post_exception), 'with_repo releases after callback exception');
275-
if (! is_wp_error($post_exception) ) {
276-
$post_exception->release();
277-
}
297+
if (! is_wp_error($post_exception) ) {
298+
$post_exception->release();
299+
}
300+
301+
$GLOBALS['wpdb'] = new DataMachineCode_Fake_WPDB();
302+
$db_tmp = sys_get_temp_dir() . '/dmc-workspace-lock-db-smoke-' . bin2hex(random_bytes(4));
303+
mkdir($db_tmp, 0755, true);
304+
register_shutdown_function(
305+
function () use ( $db_tmp ) {
306+
if (is_dir($db_tmp) ) {
307+
exec('rm -rf ' . escapeshellarg($db_tmp));
308+
}
309+
}
310+
);
311+
$db_first = \DataMachineCode\Workspace\WorkspaceMutationLock::acquire($db_tmp, 'demo', 1);
312+
$db_busy = \DataMachineCode\Workspace\WorkspaceMutationLock::acquire($db_tmp, 'demo', 0);
313+
$db_data = is_wp_error($db_busy) ? $db_busy->get_error_data() : array();
314+
$assert(true, is_wp_error($db_busy), 'DB-backed same repo acquisition fails fast while held');
315+
$assert('demo', (string) ( $db_data['active_lock']['scope'] ?? '' ), 'busy failure includes active DB lock scope');
316+
$assert('worktree-demo', (string) ( $db_data['active_lock']['lock_key'] ?? '' ), 'busy failure includes active DB lock key');
317+
$assert(true, isset($db_data['active_lock']['owner']), 'busy failure includes active DB lock owner');
318+
$assert(true, isset($db_data['active_lock']['acquired_at']), 'busy failure includes acquired timestamp');
319+
$assert(true, isset($db_data['active_lock']['heartbeat_at']), 'busy failure includes heartbeat timestamp');
320+
$assert(true, isset($db_data['active_lock']['expires_at']), 'busy failure includes expires timestamp');
321+
$assert(true, isset($db_data['active_lock']['retry_after_seconds']), 'busy failure includes retry-after seconds');
322+
$assert(true, isset($db_data['active_lock']['age_seconds']), 'busy failure includes age seconds');
323+
$assert(true, isset($db_data['active_lock']['metadata']['owner_context']), 'busy failure includes owner context metadata');
324+
if (! is_wp_error($db_first) ) {
325+
$db_first->release();
326+
}
278327

279-
echo "\nResult: " . ( $total - $failures ) . "/{$total} passed\n";
328+
echo "\nResult: " . ( $total - $failures ) . "/{$total} passed\n";
280329
exit($failures > 0 ? 1 : 0);
281330
}

0 commit comments

Comments
 (0)