From d398cf4a37b26f5553449cb87db8fad29aa02b94 Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Tue, 23 Jun 2026 17:21:02 -0400 Subject: [PATCH] better logging --- ...cf211a943c533e38e887d2c12713c78b687d.json} | 17 +++++++++-- .../list_pending_seedance2pro_video_jobs.rs | 12 ++++++-- .../order_polling_main_loop.rs | 29 ++++++++++++++++--- 3 files changed, 49 insertions(+), 9 deletions(-) rename .sqlx/{query-ddbbd3886c00268edd3993508f635549fc8ddc877bb059fd58f14b8c07586fc9.json => query-1703bc63ce65d98cbcad81d515cbcf211a943c533e38e887d2c12713c78b687d.json} (83%) diff --git a/.sqlx/query-ddbbd3886c00268edd3993508f635549fc8ddc877bb059fd58f14b8c07586fc9.json b/.sqlx/query-1703bc63ce65d98cbcad81d515cbcf211a943c533e38e887d2c12713c78b687d.json similarity index 83% rename from .sqlx/query-ddbbd3886c00268edd3993508f635549fc8ddc877bb059fd58f14b8c07586fc9.json rename to .sqlx/query-1703bc63ce65d98cbcad81d515cbcf211a943c533e38e887d2c12713c78b687d.json index a0ad19008e..b88037b37d 100644 --- a/.sqlx/query-ddbbd3886c00268edd3993508f635549fc8ddc877bb059fd58f14b8c07586fc9.json +++ b/.sqlx/query-1703bc63ce65d98cbcad81d515cbcf211a943c533e38e887d2c12713c78b687d.json @@ -1,6 +1,6 @@ { "db_name": "MySQL", - "query": "\nSELECT\n jobs.token as `job_token: tokens::tokens::generic_inference_jobs::InferenceJobToken`,\n jobs.maybe_external_third_party_id as `order_id`,\n jobs.maybe_creator_user_token as `maybe_creator_user_token: tokens::tokens::users::UserToken`,\n jobs.maybe_creator_anonymous_visitor_token as `maybe_creator_anonymous_visitor_token: tokens::tokens::anonymous_visitor_tracking::AnonymousVisitorTrackingToken`,\n jobs.creator_ip_address,\n jobs.creator_set_visibility as `creator_set_visibility: enums::common::visibility::Visibility`,\n jobs.maybe_prompt_token as `maybe_prompt_token: tokens::tokens::prompts::PromptToken`,\n jobs.maybe_wallet_ledger_entry_token as `maybe_wallet_ledger_entry_token: tokens::tokens::wallet_ledger_entries::WalletLedgerEntryToken`,\n jobs.platform_type as `maybe_platform_type: enums::common::platform_type::PlatformType`\n\nFROM generic_inference_jobs as jobs\n\nWHERE jobs.maybe_external_third_party = ?\n AND jobs.job_type = ?\n AND jobs.status NOT IN ('complete_success', 'complete_failure')\n AND jobs.maybe_external_third_party_id IS NOT NULL\n\nLIMIT 25000\n ", + "query": "\nSELECT\n jobs.token as `job_token: tokens::tokens::generic_inference_jobs::InferenceJobToken`,\n jobs.maybe_external_third_party_id as `order_id`,\n jobs.maybe_creator_user_token as `maybe_creator_user_token: tokens::tokens::users::UserToken`,\n jobs.maybe_creator_anonymous_visitor_token as `maybe_creator_anonymous_visitor_token: tokens::tokens::anonymous_visitor_tracking::AnonymousVisitorTrackingToken`,\n jobs.creator_ip_address,\n jobs.creator_set_visibility as `creator_set_visibility: enums::common::visibility::Visibility`,\n jobs.maybe_prompt_token as `maybe_prompt_token: tokens::tokens::prompts::PromptToken`,\n jobs.maybe_wallet_ledger_entry_token as `maybe_wallet_ledger_entry_token: tokens::tokens::wallet_ledger_entries::WalletLedgerEntryToken`,\n jobs.platform_type as `maybe_platform_type: enums::common::platform_type::PlatformType`,\n jobs.created_at\n\nFROM generic_inference_jobs as jobs\n\nWHERE jobs.maybe_external_third_party = ?\n AND jobs.job_type = ?\n AND jobs.status NOT IN ('complete_success', 'complete_failure')\n AND jobs.maybe_external_third_party_id IS NOT NULL\n\nLIMIT 25000\n ", "describe": { "columns": [ { @@ -92,6 +92,16 @@ "char_set": 224, "max_size": 64 } + }, + { + "ordinal": 9, + "name": "created_at", + "type_info": { + "type": "Timestamp", + "flags": "NOT_NULL | MULTIPLE_KEY | BINARY | TIMESTAMP", + "char_set": 63, + "max_size": 19 + } } ], "parameters": { @@ -106,8 +116,9 @@ false, true, true, - true + true, + false ] }, - "hash": "ddbbd3886c00268edd3993508f635549fc8ddc877bb059fd58f14b8c07586fc9" + "hash": "1703bc63ce65d98cbcad81d515cbcf211a943c533e38e887d2c12713c78b687d" } diff --git a/crates/schema/database/mysql_queries/src/queries/generic_inference/api_providers/seedance2pro/list_pending_seedance2pro_video_jobs.rs b/crates/schema/database/mysql_queries/src/queries/generic_inference/api_providers/seedance2pro/list_pending_seedance2pro_video_jobs.rs index abf321f0e1..53ba201b69 100644 --- a/crates/schema/database/mysql_queries/src/queries/generic_inference/api_providers/seedance2pro/list_pending_seedance2pro_video_jobs.rs +++ b/crates/schema/database/mysql_queries/src/queries/generic_inference/api_providers/seedance2pro/list_pending_seedance2pro_video_jobs.rs @@ -1,3 +1,4 @@ +use chrono::{DateTime, Utc}; use log::warn; use sqlx::MySqlPool; @@ -29,9 +30,13 @@ pub struct PendingSeedance2ProJob { pub maybe_wallet_ledger_entry_token: Option, pub maybe_platform_type: Option, + + /// When the job row was created. Useful for surfacing how long the oldest + /// pending job has been waiting. + pub created_at: DateTime, } -#[derive(Debug, Default)] +#[derive(Debug)] struct RawRecord { job_token: InferenceJobToken, order_id: Option, @@ -42,6 +47,7 @@ struct RawRecord { maybe_prompt_token: Option, maybe_wallet_ledger_entry_token: Option, maybe_platform_type: Option, + created_at: DateTime, } /// Returns all non-terminal Seedance2Pro video jobs that have an associated order_id. @@ -62,7 +68,8 @@ SELECT jobs.creator_set_visibility as `creator_set_visibility: enums::common::visibility::Visibility`, jobs.maybe_prompt_token as `maybe_prompt_token: tokens::tokens::prompts::PromptToken`, jobs.maybe_wallet_ledger_entry_token as `maybe_wallet_ledger_entry_token: tokens::tokens::wallet_ledger_entries::WalletLedgerEntryToken`, - jobs.platform_type as `maybe_platform_type: enums::common::platform_type::PlatformType` + jobs.platform_type as `maybe_platform_type: enums::common::platform_type::PlatformType`, + jobs.created_at FROM generic_inference_jobs as jobs @@ -100,6 +107,7 @@ LIMIT 25000 maybe_prompt_token: record.maybe_prompt_token, maybe_wallet_ledger_entry_token: record.maybe_wallet_ledger_entry_token, maybe_platform_type: record.maybe_platform_type, + created_at: record.created_at, }) }) .collect(); diff --git a/crates/service/job/seedance2_pro_job/src/jobs/order_polling_job/order_polling_main_loop.rs b/crates/service/job/seedance2_pro_job/src/jobs/order_polling_job/order_polling_main_loop.rs index cb85d72979..2d89fc81c7 100644 --- a/crates/service/job/seedance2_pro_job/src/jobs/order_polling_job/order_polling_main_loop.rs +++ b/crates/service/job/seedance2_pro_job/src/jobs/order_polling_job/order_polling_main_loop.rs @@ -143,6 +143,7 @@ async fn walk_orders( .collect(); let pending_db_job_count = job_by_order_id.len(); + let oldest_pending_created_at = job_by_order_id.values().map(|job| job.created_at).min(); let iteration_start = Instant::now(); let mut result = WalkResult::default(); @@ -159,18 +160,27 @@ async fn walk_orders( // itself fails, we still have the surrounding context in the logs. let iteration_elapsed = iteration_start.elapsed(); + let pending_db_jobs_display = match oldest_pending_created_at { + Some(oldest) if pending_db_job_count > 0 => format!( + "{} (oldest: {} ago)", + pending_db_job_count, + format_duration_ago(Utc::now() - oldest), + ), + _ => pending_db_job_count.to_string(), + }; + info!( "Requesting Kinovi page:\n \ - page: {page}\n \ - cursor: {cursor:?}\n \ + kinovi page: {page}\n \ + kinovi cursor: {cursor:?}\n \ orders seen so far: {orders_seen}\n \ - pending DB jobs: {pending}\n \ + pending DB jobs: {pending_db}\n \ reconciler backlog: {backlog} order(s) awaiting processing\n \ iteration elapsed: {secs}s ({millis}ms)", page = result.pages_seen, cursor = cursor, orders_seen = result.orders_seen, - pending = pending_db_job_count, + pending_db = pending_db_jobs_display, backlog = deps.order_reconciler.len(), secs = iteration_elapsed.as_secs(), millis = iteration_elapsed.as_millis(), @@ -309,6 +319,17 @@ fn stage_finished_orders( PageStageSummary { staged } } +/// Format a positive elapsed duration as `"{h} hours {m} minutes {s} seconds"` +/// (hours are unbounded; e.g. a 50-hour-old job reads `"50 hours ..."`). +/// Negative durations clamp to zero. +fn format_duration_ago(elapsed: chrono::Duration) -> String { + let total_seconds = elapsed.num_seconds().max(0); + let hours = total_seconds / 3600; + let minutes = (total_seconds % 3600) / 60; + let seconds = total_seconds % 60; + format!("{} hours {} minutes {} seconds", hours, minutes, seconds) +} + /// Poll orders from Kinovi with retries. On transient failures, waits with /// increasing delay (attempt × 2s, capped at `poll_retry_max_delay_millis`). /// After exhausting retries, alerts the pager and returns an error.