collective
Browse / github.com/storytold/artcraft / patch
Investigate Sora client latency logs (#1069)
Investigate Sora client latency logs (#1069) ## Summary - On ArtCraft Sora (`sora_2` / `sora_2_pro`) task success or failure, log structured client elapsed ms with model, plan slug, and inference job token. - No poll-interval or generation behavior changes. Companion backend metrics PR is in `artcraft-services` on the same branch name. Tracks [#1069](https://github.com/storytold/artcraft/issues/1069). **Investigation only** — fix PR deferred until admin reviews Datadog data. ## Test plan - [ ] Complete (or fail) a Sora ArtCraft video task and confirm the structured `info` log line - [ ] Confirm non-Sora video completions are unchanged
- Status
- open
- Score
- 0.00
- Adopters
- 0 other operators
- Author
- giorgioabbruscato (imported from pull request #2282, open)
- Base
d4e4ac69bbd93d237eaf5d0260bc6a5ff3a5e373- Size
- +84 −1 in 5 files
- Review
- pending
- Shared
- 2026-10-28
- Id
bc892f2d4e6bd4d102547f8c
How it went
No other operator has reported using it yet.
Diff
raw · crates/desktop/artcraft/src/services/storyteller/threads/storyteller_task_polling_thread/handle_storyteller_failed_job.rs crates/desktop/artcraft/src/services/storyteller/threads/storyteller_task_polling_thread/handle_storyteller_successful_job.rs crates/desktop/artcraft/src/services/storyteller/threads/storyteller_task_polling_thread/mod.rs crates/desktop/artcraft/src/services/storyteller/threads/storyteller_task_polling_thread/sora_latency_client_log.rs crates/desktop/artcraft/src/services/storyteller/threads/storyteller_task_polling_thread/storyteller_task_polling_thread.rs
@@ -1,10 +1,13 @@ use crate::core::events::generation_events::common::GenerationModel; use crate::core::events::basic_sendable_event_trait::BasicSendableEvent; use crate::core::events::generation_events::generation_failed_event::GenerationFailedEvent;+use crate::core::state::app_env_configs::app_env_configs::AppEnvConfigs; use crate::core::state::task_database::TaskDatabase; use crate::core::utils::enum_conversion::generation_provider::to_generation_service_provider; use crate::core::utils::enum_conversion::task_type::to_generation_action;+use super::sora_latency_client_log::maybe_log_sora_client_completion; use artcraft_api_defs::jobs::list_session_jobs::ListSessionJobsItem;+use artcraft_client::credentials::storyteller_credential_set::StorytellerCredentialSet; use enums::tauri::tasks::task_status::TaskStatus; use errors::AnyhowResult; use log::info;@@ -16,6 +19,8 @@ use sqlite_tasks::queries::update_task_status_with_rich_failure::{update_task_st pub async fn handle_failed_job( app_handle: &AppHandle,+ app_env_configs: &AppEnvConfigs,+ maybe_creds: Option<&StorytellerCredentialSet>, job: &ListSessionJobsItem, task: &Task, task_database: &TaskDatabase,@@ -37,6 +42,8 @@ pub async fn handle_failed_job( maybe_failure_message, }).await?; + maybe_log_sora_client_completion(app_env_configs, maybe_creds, job, task, "failure").await;+ let service = to_generation_service_provider(task.provider); let action = to_generation_action(task.task_type); @@ -8,6 +8,7 @@ use crate::core::utils::enum_conversion::generation_provider::to_generation_serv use crate::core::utils::enum_conversion::task_type::to_generation_action; use crate::core::utils::auto_download::{auto_download_task, clear_auto_download_checkpoint}; use super::events::maybe_handle_frontend_caller_notification::maybe_handle_frontend_caller_notification;+use super::sora_latency_client_log::maybe_log_sora_client_completion; use artcraft_api_defs::jobs::list_session_jobs::ListSessionJobsItem; use artcraft_api_defs::utils::media_links_to_thumbnail_template::media_links_to_thumbnail_template; use artcraft_client::credentials::storyteller_credential_set::StorytellerCredentialSet;@@ -62,6 +63,8 @@ pub async fn handle_successful_job( clear_auto_download_checkpoint(app_handle, task); send_additional_success_events(app_handle, app_env_configs, creds, job, task).await; + maybe_log_sora_client_completion(app_env_configs, creds, job, task, "success").await;+ let service = to_generation_service_provider(task.provider); let action = to_generation_action(task.task_type); @@ -1,4 +1,5 @@ mod events; mod handle_storyteller_failed_job; mod handle_storyteller_successful_job;+mod sora_latency_client_log; pub mod storyteller_task_polling_thread;new file mode 100644@@ -0,0 +1,72 @@+//! Client-side wall-clock log for Sora ArtCraft jobs (#1069 investigation).+//! No behavior change — structured `info!` only.++use crate::core::state::app_env_configs::app_env_configs::AppEnvConfigs;+use artcraft_api_defs::jobs::list_session_jobs::ListSessionJobsItem;+use artcraft_api_defs::subscriptions::get_session_subscription::GetSessionSubscriptionResponse;+use artcraft_client::credentials::storyteller_credential_set::StorytellerCredentialSet;+use artcraft_client::endpoints::subscriptions::get_session_subscription::get_session_subscription;+use chrono::Utc;+use enums::common::payments_namespace::PaymentsNamespace;+use enums::tauri::tasks::task_model_type::TaskModelType;+use log::{info, warn};+use sqlite_tasks::queries::task::Task;++fn is_sora_model(model: Option<&TaskModelType>) -> Option<&'static str> {+ match model {+ Some(TaskModelType::Sora2) => Some("sora_2"),+ Some(TaskModelType::Sora2Pro) => Some("sora_2_pro"),+ _ => None,+ }+}++fn plan_tag_from_subscription_response(response: &GetSessionSubscriptionResponse) -> &'static str {+ match response.active_subscription.as_ref().map(|s| s.product_slug.as_str()) {+ None => "free",+ Some("artcraft_basic") => "artcraft_basic",+ Some("artcraft_pro") => "artcraft_pro",+ Some("artcraft_max") => "artcraft_max",+ Some(_) => "unknown",+ }+}++/// Best-effort structured log when a Sora ArtCraft task completes locally.+pub async fn maybe_log_sora_client_completion(+ app_env_configs: &AppEnvConfigs,+ maybe_creds: Option<&StorytellerCredentialSet>,+ job: &ListSessionJobsItem,+ task: &Task,+ outcome: &str,+) {+ let Some(model) = is_sora_model(task.model_type.as_ref()) else {+ return;+ };++ let plan = match get_session_subscription(+ &app_env_configs.storyteller_host,+ maybe_creds,+ PaymentsNamespace::Artcraft,+ )+ .await+ {+ Ok(response) => plan_tag_from_subscription_response(&response),+ Err(err) => {+ warn!(+ "Sora latency client log: subscription lookup failed (using unknown): {:?}",+ err+ );+ "unknown"+ }+ };++ let elapsed_ms = (Utc::now() - job.created_at).num_milliseconds().max(0);+ let job_token = task+ .provider_job_id+ .as_deref()+ .unwrap_or(job.job_token.as_str());++ info!(+ "sora_latency_client model={} plan={} outcome={} client_elapsed_ms={} inference_job_token={}",+ model, plan, outcome, elapsed_ms, job_token+ );+}@@ -119,7 +119,7 @@ async fn polling_loop( TaskStatus::CompleteFailure => continue, // NB: We're done with this task. _ => {} }- handle_failed_job(app_handle, job, task, task_database).await?;+ handle_failed_job(app_handle, app_env_configs, creds.as_ref(), job, task, task_database).await?; } _ => continue, }