From c2dc39023d232802330be13be1c5fe303f429132 Mon Sep 17 00:00:00 2001 From: "John R. D'Orazio" Date: Wed, 10 Jun 2026 23:46:41 -0400 Subject: [PATCH] feat(submissions): diagnostic logging across the translation-enqueue phases MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Today's investigation into post 1508 (Eucharistic Miracles) cost a lot of time because cdcf_enqueue_translations_for_submission ran with almost no observability — the function only logged on explicit failure paths (Polylang inactive, source missing, individual wp_insert_post failure, atomic save returning false). All the SILENT happy paths and the "all langs already linked" no-op path were invisible to production log greps. For 1508 the actual sequence was: ENTER post_id=1508 pre_seed={en:1508} PHASE_1_DONE newly_created={it:1511, es:1512, fr:1513, pt:1514, de:1515} PHASE_2_OK final_group={en:1508, it:1511, ...} PHASE_3_DONE queued 5 jobs via redis None of which we could see in the FPM logs — only the worker's "Translation complete for post N (lang)" lines from cdcf_process_translation. We had to grep the access log and reconstruct timing from worker completion timestamps to figure out the hook had actually succeeded and the Polylang group disconnected SOMEHOW between hook completion (03:00:28) and the next hook fire (03:21:00). This adds 5 structured error_log lines at each phase transition with a uniform shape: ENTER post_id=X post_type=Y pre_seed_group={...} PHASE_1_DONE post_id=X newly_created={...} already_linked={...} PHASE_2_OK post_id=X atomic group save succeeded; final_group={...} (or already-existing PHASE_2_FAIL on save returning false) PHASE_3_DONE post_id=X queued N job(s) via redis|wp-cron: {...} NO_OP post_id=X (all target langs already pre-seeded) Each line is a single grep -E 'PHASE_|ENTER|NO_OP' away from a complete timeline. Volume: ~3-5 lines per submission publish (one publish per public referral approval, so a few per week max). Per- sibling worker logs (1 per translation) are unchanged. New helper cdcf_format_lang_map() centralizes the {lang:id} formatting so the lines are consistent and parseable. 4 unit tests for it: empty array, single entry, 6-language order preservation, string->int coercion. 553/553 theme suite green. No production behavior change — purely additional logging. Co-Authored-By: Claude Opus 4.7 (1M context) --- .../includes/admin/submission-lifecycle.php | 58 ++++++++++++++++++- .../tests/SubmissionLifecycleTest.php | 30 ++++++++++ 2 files changed, 85 insertions(+), 3 deletions(-) diff --git a/wordpress/themes/cdcf-headless/includes/admin/submission-lifecycle.php b/wordpress/themes/cdcf-headless/includes/admin/submission-lifecycle.php index f30fa90..b374da2 100644 --- a/wordpress/themes/cdcf-headless/includes/admin/submission-lifecycle.php +++ b/wordpress/themes/cdcf-headless/includes/admin/submission-lifecycle.php @@ -95,12 +95,21 @@ function cdcf_enqueue_translations_for_submission(int $en_post_id, string $post_ $translations = pll_get_post_translations($en_post_id); $translations['en'] = $en_post_id; + error_log(sprintf( + 'cdcf_enqueue_translations_for_submission: ENTER post_id=%d post_type=%s pre_seed_group=%s', + $en_post_id, + $post_type, + cdcf_format_lang_map($translations) + )); + // Phase 1: create draft siblings + per-post language assignment. // Group save is intentionally NOT called here — see file-level // docblock for the lost-update race rationale. - $newly_created = []; + $newly_created = []; + $already_linked = []; foreach ($target_langs as $lang) { if (!empty($translations[$lang])) { + $already_linked[$lang] = (int) $translations[$lang]; continue; } @@ -120,8 +129,19 @@ function cdcf_enqueue_translations_for_submission(int $en_post_id, string $post_ $newly_created[$lang] = $trans_id; } + error_log(sprintf( + 'cdcf_enqueue_translations_for_submission: PHASE_1_DONE post_id=%d newly_created=%s already_linked=%s', + $en_post_id, + cdcf_format_lang_map($newly_created), + cdcf_format_lang_map($already_linked) + )); + if (empty($newly_created)) { // Nothing new to link or enqueue. + error_log(sprintf( + 'cdcf_enqueue_translations_for_submission: NO_OP post_id=%d (all target langs already pre-seeded); exiting without group save.', + $en_post_id + )); return; } @@ -129,9 +149,10 @@ function cdcf_enqueue_translations_for_submission(int $en_post_id, string $post_ $save_result = pll_save_post_translations($translations); if ($save_result === false) { error_log(sprintf( - 'cdcf_enqueue_translations_for_submission: pll_save_post_translations returned false for post %d; rolling back %d draft(s).', + 'cdcf_enqueue_translations_for_submission: PHASE_2_FAIL post_id=%d pll_save_post_translations returned false; rolling back %d draft(s): %s', $en_post_id, - count($newly_created) + count($newly_created), + cdcf_format_lang_map($newly_created) )); foreach ($newly_created as $trans_id) { wp_delete_post($trans_id, true); @@ -139,8 +160,15 @@ function cdcf_enqueue_translations_for_submission(int $en_post_id, string $post_ return; } + error_log(sprintf( + 'cdcf_enqueue_translations_for_submission: PHASE_2_OK post_id=%d atomic group save succeeded; final_group=%s', + $en_post_id, + cdcf_format_lang_map($translations) + )); + // Phase 3: enqueue translation jobs for the newly-created siblings only. // (Existing siblings from the pre-seed already had their content done.) + $queue_name = function_exists('cdcf_enqueue_translation') ? 'redis' : 'wp-cron'; foreach ($newly_created as $lang => $trans_id) { if (function_exists('cdcf_enqueue_translation')) { cdcf_enqueue_translation($trans_id, $en_post_id, $lang); @@ -149,6 +177,30 @@ function cdcf_enqueue_translations_for_submission(int $en_post_id, string $post_ spawn_cron(); } } + + error_log(sprintf( + 'cdcf_enqueue_translations_for_submission: PHASE_3_DONE post_id=%d queued %d job(s) via %s: %s', + $en_post_id, + count($newly_created), + $queue_name, + cdcf_format_lang_map($newly_created) + )); +} + +/** + * Format a {lang => post_id} map for compact inclusion in error_log + * lines. Returns "{lang:id, lang:id, ...}" or "{}" if empty. + * Used by the diagnostic logs in cdcf_enqueue_translations_for_submission. + */ +function cdcf_format_lang_map(array $map): string { + if (empty($map)) { + return '{}'; + } + $parts = []; + foreach ($map as $lang => $id) { + $parts[] = $lang . ':' . (int) $id; + } + return '{' . implode(', ', $parts) . '}'; } /** diff --git a/wordpress/themes/cdcf-headless/tests/SubmissionLifecycleTest.php b/wordpress/themes/cdcf-headless/tests/SubmissionLifecycleTest.php index 6fb6554..d45cee4 100644 --- a/wordpress/themes/cdcf-headless/tests/SubmissionLifecycleTest.php +++ b/wordpress/themes/cdcf-headless/tests/SubmissionLifecycleTest.php @@ -423,6 +423,36 @@ function (int $id, bool $force) use (&$deleted): array { ); } + // ─── cdcf_format_lang_map ───────────────────────────────────────── + + public function test_format_lang_map_empty_array_returns_curly_braces(): void + { + $this->assertSame('{}', cdcf_format_lang_map([])); + } + + public function test_format_lang_map_single_entry(): void + { + $this->assertSame('{en:42}', cdcf_format_lang_map(['en' => 42])); + } + + public function test_format_lang_map_six_languages_preserves_input_order(): void + { + // The diagnostic log lines rely on stable key order (en first when + // pre-seeding, target langs in target_langs order otherwise) — assert + // PHP's insertion-order array iteration carries through. + $this->assertSame( + '{en:1508, it:1521, es:1522, fr:1523, pt:1524, de:1525}', + cdcf_format_lang_map(['en' => 1508, 'it' => 1521, 'es' => 1522, 'fr' => 1523, 'pt' => 1524, 'de' => 1525]) + ); + } + + public function test_format_lang_map_coerces_string_ids_to_int(): void + { + // ACF and some Polylang return paths hand back string-numeric IDs; + // the helper coerces them so the log line is uniform. + $this->assertSame('{en:10, it:11}', cdcf_format_lang_map(['en' => '10', 'it' => '11'])); + } + // ─── cdcf_repend_submission_on_untrash ──────────────────────────── public function test_repend_ignores_status_transitions_that_arent_trash_to_draft(): void