Include request spans in JSON app-server logs

codex-rs/app-server/src/lib.rs

@@ -585,6 +585,8 @@ pub async fn run_main_with_transport_options(
     let stderr_fmt: StderrLogLayer = match log_format_from_env() {
         LogFormat::Json => tracing_subscriber::fmt::layer()
             .json()
+            .with_current_span(true)
+            .with_span_list(true)
             .with_writer(std::io::stderr)
             .with_span_events(tracing_subscriber::fmt::format::FmtSpan::FULL)
             .with_filter(EnvFilter::from_default_env())

codex-rs/app-server/src/request_processors/plugins.rs

@@ -248,36 +248,75 @@ impl PluginRequestProcessor {
         &self,
         params: PluginListParams,
     ) -> Result<PluginListResponse, JSONRPCErrorError> {
+        let started_at = Instant::now();
         let plugins_manager = self.thread_manager.plugins_manager();
         let PluginListParams { cwds } = params;
         let roots = cwds.unwrap_or_default();
+        info!(cwd_count = roots.len(), "plugin/list started");
 
+        let phase_started_at = Instant::now();
         let config = self.load_latest_config(/*fallback_cwd*/ None).await?;
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            total_elapsed_ms = started_at.elapsed().as_millis(),
+            plugins_enabled = config.features.enabled(Feature::Plugins),
+            remote_plugin_enabled = config.features.enabled(Feature::RemotePlugin),
+            "plugin/list loaded config"
+        );
         let empty_response = || PluginListResponse {
             marketplaces: Vec::new(),
             marketplace_load_errors: Vec::new(),
             featured_plugin_ids: Vec::new(),
         };
         if !config.features.enabled(Feature::Plugins) {
+            info!(
+                total_elapsed_ms = started_at.elapsed().as_millis(),
+                "plugin/list returning empty response; plugins feature disabled"
+            );
             return Ok(empty_response());
         }
+        let phase_started_at = Instant::now();
         let auth = self.auth_manager.auth().await;
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            total_elapsed_ms = started_at.elapsed().as_millis(),
+            authenticated = auth.is_some(),
+            "plugin/list loaded auth state"
+        );
+        let phase_started_at = Instant::now();
         if !self
             .workspace_codex_plugins_enabled(&config, auth.as_ref())
             .await
         {
+            info!(
+                elapsed_ms = phase_started_at.elapsed().as_millis(),
+                total_elapsed_ms = started_at.elapsed().as_millis(),
+                "plugin/list returning empty response; workspace disabled Codex plugins"
+            );
             return Ok(empty_response());
         }
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            total_elapsed_ms = started_at.elapsed().as_millis(),
+            "plugin/list checked workspace Codex plugins setting"
+        );
         let plugins_input = config.plugins_config_input();
+        let phase_started_at = Instant::now();
         plugins_manager.maybe_start_plugin_list_background_tasks_for_config(
             &plugins_input,
             auth.clone(),
             &roots,
             Some(self.effective_plugins_changed_callback(config.clone())),
         );
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            total_elapsed_ms = started_at.elapsed().as_millis(),
+            "plugin/list scheduled background refresh tasks"
+        );
 
         let config_for_marketplace_listing = plugins_input.clone();
         let plugins_manager_for_marketplace_listing = plugins_manager.clone();
+        let phase_started_at = Instant::now();
         let (mut data, marketplace_load_errors) = match tokio::task::spawn_blocking(move || {
             let outcome = plugins_manager_for_marketplace_listing
                 .list_marketplaces_for_config(&config_for_marketplace_listing, &roots)?;
@@ -334,11 +373,25 @@ impl PluginRequestProcessor {
                 )));
             }
         };
+        let marketplace_count = data.len();
+        let plugin_count = data
+            .iter()
+            .map(|marketplace| marketplace.plugins.len())
+            .sum::<usize>();
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            total_elapsed_ms = started_at.elapsed().as_millis(),
+            marketplace_count,
+            plugin_count,
+            load_error_count = marketplace_load_errors.len(),
+            "plugin/list listed local marketplaces"
+        );
 
         if config.features.enabled(Feature::RemotePlugin) {
             let remote_plugin_service_config = RemotePluginServiceConfig {
                 chatgpt_base_url: config.chatgpt_base_url.clone(),
             };
+            let phase_started_at = Instant::now();
             match codex_core_plugins::remote::fetch_remote_marketplaces(
                 &remote_plugin_service_config,
                 auth.as_ref(),
@@ -346,6 +399,11 @@ impl PluginRequestProcessor {
             .await
             {
                 Ok(remote_marketplaces) => {
+                    let remote_marketplace_count = remote_marketplaces.len();
+                    let remote_plugin_count = remote_marketplaces
+                        .iter()
+                        .map(|marketplace| marketplace.plugins.len())
+                        .sum::<usize>();
                     for remote_marketplace in remote_marketplaces
                         .into_iter()
                         .map(remote_marketplace_to_info)
@@ -359,14 +417,29 @@ impl PluginRequestProcessor {
                             data.push(remote_marketplace);
                         }
                     }
+                    info!(
+                        elapsed_ms = phase_started_at.elapsed().as_millis(),
+                        total_elapsed_ms = started_at.elapsed().as_millis(),
+                        remote_marketplace_count,
+                        remote_plugin_count,
+                        "plugin/list fetched remote marketplaces"
+                    );
                 }
                 Err(
                     RemotePluginCatalogError::AuthRequired
                     | RemotePluginCatalogError::UnsupportedAuthMode,
-                ) => {}
+                ) => {
+                    info!(
+                        elapsed_ms = phase_started_at.elapsed().as_millis(),
+                        total_elapsed_ms = started_at.elapsed().as_millis(),
+                        "plugin/list skipped remote marketplace fetch; remote catalog auth unavailable"
+                    );
+                }
                 Err(err) => {
                     warn!(
                         error = %err,
+                        elapsed_ms = phase_started_at.elapsed().as_millis(),
+                        total_elapsed_ms = started_at.elapsed().as_millis(),
                         "plugin/list remote plugin catalog fetch failed; returning local marketplaces only"
                     );
                 }
@@ -377,23 +450,52 @@ impl PluginRequestProcessor {
             .iter()
             .any(|marketplace| marketplace.name == OPENAI_CURATED_MARKETPLACE_NAME)
         {
+            let phase_started_at = Instant::now();
             match plugins_manager
                 .featured_plugin_ids_for_config(&plugins_input, auth.as_ref())
                 .await
             {
-                Ok(featured_plugin_ids) => featured_plugin_ids,
+                Ok(featured_plugin_ids) => {
+                    info!(
+                        elapsed_ms = phase_started_at.elapsed().as_millis(),
+                        total_elapsed_ms = started_at.elapsed().as_millis(),
+                        featured_plugin_id_count = featured_plugin_ids.len(),
+                        "plugin/list fetched featured plugin ids"
+                    );
+                    featured_plugin_ids
+                }
                 Err(err) => {
                     warn!(
                         error = %err,
+                        elapsed_ms = phase_started_at.elapsed().as_millis(),
+                        total_elapsed_ms = started_at.elapsed().as_millis(),
                         "plugin/list featured plugin fetch failed; returning empty featured ids"
                     );
                     Vec::new()
                 }
             }
         } else {
+            info!(
+                total_elapsed_ms = started_at.elapsed().as_millis(),
+                "plugin/list skipped featured plugin ids; curated marketplace unavailable"
+            );
             Vec::new()
         };
 
+        let marketplace_count = data.len();
+        let plugin_count = data
+            .iter()
+            .map(|marketplace| marketplace.plugins.len())
+            .sum::<usize>();
+        info!(
+            total_elapsed_ms = started_at.elapsed().as_millis(),
+            marketplace_count,
+            plugin_count,
+            load_error_count = marketplace_load_errors.len(),
+            featured_plugin_id_count = featured_plugin_ids.len(),
+            "plugin/list completed"
+        );
+
         Ok(PluginListResponse {
             marketplaces: data,
             marketplace_load_errors,

codex-rs/core-plugins/src/manager.rs

@@ -775,8 +775,13 @@ impl PluginsManager {
 
         let cache_key = featured_plugin_ids_cache_key(config, auth);
         if let Some(featured_plugin_ids) = self.cached_featured_plugin_ids(&cache_key) {
+            info!(
+                featured_plugin_id_count = featured_plugin_ids.len(),
+                "reused featured plugin ids cache"
+            );
             return Ok(featured_plugin_ids);
         }
+        let started_at = Instant::now();
         let featured_plugin_ids = crate::remote_legacy::fetch_remote_featured_plugin_ids(
             &remote_plugin_service_config(config),
             auth,
@@ -784,6 +789,11 @@ impl PluginsManager {
         )
         .await?;
         self.write_featured_plugin_ids_cache(cache_key, &featured_plugin_ids);
+        info!(
+            elapsed_ms = started_at.elapsed().as_millis(),
+            featured_plugin_id_count = featured_plugin_ids.len(),
+            "refreshed featured plugin ids cache"
+        );
         Ok(featured_plugin_ids)
     }
 
@@ -1160,13 +1170,39 @@ impl PluginsManager {
         config: &PluginsConfigInput,
         additional_roots: &[AbsolutePathBuf],
     ) -> Result<ConfiguredMarketplaceListOutcome, MarketplaceError> {
+        let started_at = Instant::now();
         if !config.plugins_enabled {
             return Ok(ConfiguredMarketplaceListOutcome::default());
         }
 
+        let phase_started_at = Instant::now();
         let (installed_plugins, enabled_plugins) = self.configured_plugin_states(config);
-        let marketplace_outcome =
-            list_marketplaces(&self.marketplace_roots(config, additional_roots))?;
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            installed_plugin_count = installed_plugins.len(),
+            enabled_plugin_count = enabled_plugins.len(),
+            "plugin/list loaded configured plugin states"
+        );
+
+        let phase_started_at = Instant::now();
+        let marketplace_roots = self.marketplace_roots(config, additional_roots);
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            additional_root_count = additional_roots.len(),
+            marketplace_root_count = marketplace_roots.len(),
+            "plugin/list built marketplace roots"
+        );
+
+        let phase_started_at = Instant::now();
+        let marketplace_outcome = list_marketplaces(&marketplace_roots)?;
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            marketplace_count = marketplace_outcome.marketplaces.len(),
+            marketplace_error_count = marketplace_outcome.errors.len(),
+            "plugin/list loaded raw marketplaces"
+        );
+
+        let phase_started_at = Instant::now();
         let mut seen_plugin_keys = HashSet::new();
         let marketplaces = marketplace_outcome
             .marketplaces
@@ -1207,8 +1243,24 @@ impl PluginsManager {
                     plugins,
                 })
             })
-            .collect();
+            .collect::<Vec<_>>();
+        let plugin_count = marketplaces
+            .iter()
+            .map(|marketplace: &ConfiguredMarketplace| marketplace.plugins.len())
+            .sum::<usize>();
+        info!(
+            elapsed_ms = phase_started_at.elapsed().as_millis(),
+            marketplace_count = marketplaces.len(),
+            plugin_count,
+            "plugin/list filtered configured marketplaces"
+        );
 
+        info!(
+            elapsed_ms = started_at.elapsed().as_millis(),
+            marketplace_count = marketplaces.len(),
+            plugin_count,
+            "plugin/list completed configured marketplace listing"
+        );
         Ok(ConfiguredMarketplaceListOutcome {
             marketplaces,
             errors: marketplace_outcome.errors,
@@ -1462,15 +1514,27 @@ impl PluginsManager {
             let config = config.clone();
             let manager = Arc::clone(self);
             tokio::spawn(async move {
+                let started_at = Instant::now();
+                info!("warming featured plugin ids cache at app-server startup");
                 let auth = auth_manager.auth().await;
-                if let Err(err) = manager
+                match manager
                     .featured_plugin_ids_for_config(&config, auth.as_ref())
                     .await
                 {
-                    warn!(
-                        error = %err,
-                        "failed to warm featured plugin ids cache"
-                    );
+                    Ok(featured_plugin_ids) => {
+                        info!(
+                            elapsed_ms = started_at.elapsed().as_millis(),
+                            featured_plugin_id_count = featured_plugin_ids.len(),
+                            "warmed featured plugin ids cache at app-server startup"
+                        );
+                    }
+                    Err(err) => {
+                        warn!(
+                            error = %err,
+                            elapsed_ms = started_at.elapsed().as_millis(),
+                            "failed to warm featured plugin ids cache at app-server startup"
+                        );
+                    }
                 }
             });
         }

codex-rs/core-plugins/src/marketplace.rs

@@ -15,6 +15,8 @@ use std::io;
 use std::path::Component;
 use std::path::Path;
 use std::path::PathBuf;
+use std::time::Instant;
+use tracing::info;
 use tracing::warn;
 
 const MARKETPLACE_MANIFEST_RELATIVE_PATHS: &[&str] = &[
@@ -269,13 +271,31 @@ fn marketplace_root_from_layout(marketplace_path: &Path, relative_path: &str) ->
 }
 
 pub fn load_marketplace(path: &AbsolutePathBuf) -> Result<Marketplace, MarketplaceError> {
+    let started_at = Instant::now();
+    let phase_started_at = Instant::now();
     let marketplace = load_raw_marketplace_manifest(path)?;
+    info!(
+        elapsed_ms = phase_started_at.elapsed().as_millis(),
+        marketplace = %marketplace.name,
+        plugin_entry_count = marketplace.plugins.len(),
+        "plugin/list loaded marketplace manifest"
+    );
     let mut plugins = Vec::new();
 
     for plugin in marketplace.plugins {
+        let plugin_started_at = Instant::now();
+        let plugin_name = plugin.name.clone();
         let plugin = match resolve_marketplace_plugin_entry(path, &marketplace.name, plugin) {
             Ok(Some(plugin)) => plugin,
-            Ok(None) => continue,
+            Ok(None) => {
+                info!(
+                    elapsed_ms = plugin_started_at.elapsed().as_millis(),
+                    marketplace = %marketplace.name,
+                    plugin = %plugin_name,
+                    "plugin/list skipped marketplace plugin entry"
+                );
+                continue;
+            }
             Err(MarketplaceError::InvalidPlugin(message)) => {
                 warn!(
                     path = %path.display(),
@@ -287,6 +307,12 @@ pub fn load_marketplace(path: &AbsolutePathBuf) -> Result<Marketplace, Marketpla
             }
             Err(err) => return Err(err),
         };
+        info!(
+            elapsed_ms = plugin_started_at.elapsed().as_millis(),
+            marketplace = %marketplace.name,
+            plugin = %plugin_name,
+            "plugin/list resolved marketplace plugin entry"
+        );
 
         plugins.push(MarketplacePlugin {
             name: plugin.plugin_id.plugin_name,
@@ -296,6 +322,13 @@ pub fn load_marketplace(path: &AbsolutePathBuf) -> Result<Marketplace, Marketpla
         });
     }
 
+    info!(
+        elapsed_ms = started_at.elapsed().as_millis(),
+        marketplace = %marketplace.name,
+        plugin_count = plugins.len(),
+        "plugin/list completed marketplace load"
+    );
+
     Ok(Marketplace {
         name: marketplace.name,
         path: path.clone(),
@@ -309,11 +342,27 @@ pub fn list_marketplaces_with_home(
     additional_roots: &[AbsolutePathBuf],
     home_dir: Option<&Path>,
 ) -> Result<MarketplaceListOutcome, MarketplaceError> {
+    let started_at = Instant::now();
     let mut outcome = MarketplaceListOutcome::default();
+    let marketplace_paths = discover_marketplace_paths_from_roots(additional_roots, home_dir);
+    info!(
+        marketplace_path_count = marketplace_paths.len(),
+        additional_root_count = additional_roots.len(),
+        "plugin/list discovered marketplace paths"
+    );
 
-    for marketplace_path in discover_marketplace_paths_from_roots(additional_roots, home_dir) {
+    for marketplace_path in marketplace_paths {
+        let marketplace_started_at = Instant::now();
         match load_marketplace(&marketplace_path) {
-            Ok(marketplace) => outcome.marketplaces.push(marketplace),
+            Ok(marketplace) => {
+                info!(
+                    elapsed_ms = marketplace_started_at.elapsed().as_millis(),
+                    marketplace = %marketplace.name,
+                    plugin_count = marketplace.plugins.len(),
+                    "plugin/list loaded marketplace"
+                );
+                outcome.marketplaces.push(marketplace);
+            }
             Err(err) => {
                 warn!(
                     path = %marketplace_path.display(),
@@ -328,6 +377,12 @@ pub fn list_marketplaces_with_home(
         }
     }
 
+    info!(
+        elapsed_ms = started_at.elapsed().as_millis(),
+        marketplace_count = outcome.marketplaces.len(),
+        marketplace_error_count = outcome.errors.len(),
+        "plugin/list completed raw marketplace listing"
+    );
     Ok(outcome)
 }
 
@@ -335,11 +390,16 @@ fn discover_marketplace_paths_from_roots(
     additional_roots: &[AbsolutePathBuf],
     home_dir: Option<&Path>,
 ) -> Vec<AbsolutePathBuf> {
+    let started_at = Instant::now();
     let mut paths = Vec::new();
+    let mut home_manifest_found = false;
+    let mut direct_root_manifest_count = 0;
+    let mut repo_root_manifest_count = 0;
 
     if let Some(home) = home_dir
         && let Some(path) = find_marketplace_manifest_path(home)
     {
+        home_manifest_found = true;
         paths.push(path);
     }
 
@@ -349,6 +409,7 @@ fn discover_marketplace_paths_from_roots(
         if let Some(path) = find_marketplace_manifest_path(root.as_path())
             && !paths.contains(&path)
         {
+            direct_root_manifest_count += 1;
             paths.push(path);
             continue;
         }
@@ -357,10 +418,20 @@ fn discover_marketplace_paths_from_roots(
             && let Some(path) = find_marketplace_manifest_path(repo_root.as_path())
             && !paths.contains(&path)
         {
+            repo_root_manifest_count += 1;
             paths.push(path);
         }
     }
 
+    info!(
+        elapsed_ms = started_at.elapsed().as_millis(),
+        additional_root_count = additional_roots.len(),
+        home_manifest_found,
+        direct_root_manifest_count,
+        repo_root_manifest_count,
+        marketplace_path_count = paths.len(),
+        "plugin/list discovered marketplace paths from roots"
+    );
     paths
 }
 
@@ -398,7 +469,18 @@ fn resolve_marketplace_plugin_entry(
     };
 
     let manifest = match &source {
-        MarketplacePluginSource::Local { path } => load_plugin_manifest(path.as_path()),
+        MarketplacePluginSource::Local { path } => {
+            let started_at = Instant::now();
+            let manifest = load_plugin_manifest(path.as_path());
+            info!(
+                elapsed_ms = started_at.elapsed().as_millis(),
+                marketplace = %marketplace_name,
+                plugin = %name,
+                manifest_loaded = manifest.is_some(),
+                "plugin/list loaded local plugin manifest"
+            );
+            manifest
+        }
         MarketplacePluginSource::Git { .. } => None,
     };
     let interface = plugin_interface_with_marketplace_category(