generating slides is much slower as before #68

Open
opened 2026-05-14 03:29:13 +00:00 by despiegk · 6 comments
Owner

image

check how we generate, do we use AI agent in the cmdline?
wrong model?

![image](/attachments/a1ff3ebe-f6be-4543-b21e-f98423a6dcfe) check how we generate, do we use AI agent in the cmdline? wrong model?
342 KiB
Author
Owner

image

its all very weird what it does

![image](/attachments/38e35a8c-628f-4f7b-b345-7ecf2819d782) its all very weird what it does
432 KiB
Author
Owner

should just call hero_proc
who calls a hero_slide cmd
who calls the direct client for AI

should just call hero_proc who calls a hero_slide cmd who calls the direct client for AI
Author
Owner

could be just a logging issue

could be just a logging issue
Member

Implementation Spec for Issue #68

Root Cause Analysis

Three stacked problems were identified:

Problem 1: Startup banner pollutes job logs and causes JSON parse error

hero_slides calls print_startup_info() unconditionally on every invocation — including one-shot generate slide subcommands run by hero_proc. This prints a multi-line ===...=== banner to stdout before any valid log lines. Since hero_proc captures stdout as job log output, this banner becomes the first content in the log stream, causing the client-side JSON parser to fail with "in response (line 22, position 5)". The fix is to suppress the banner for all non-server subcommands.

Problem 2: Job logs fetched by run_id instead of job_id (likely cause of aibroker log cross-contamination)

legacy_logs_from_snapshot in generate_job.rs fetches logs from hero_proc. If it passes run_id instead of job_id, hero_proc returns logs from all jobs in that run context — including concurrently-running services like hero_aibroker. This explains why aibroker startup messages (aibroker.ui: Starting Hero AI Broker Admin, admin socket: ..., multiple scheduled job entries) appear in slide generation job logs.

Problem 3: Slowness — model selection or missing API key

The AI call chain is correct: hero_slides generate slideAiClient::get() → direct HTTP to OpenRouter (no agent subprocess, no CLI launch). The slowness is likely:

  • A per-slide image_model override set to the Pro model (Gemini Pro is 3-5x slower than Flash)
  • OR OPENROUTER_API_KEY missing from hero_proc secrets, causing AiError::ModelNotAvailable (explains the fast 3-line failure seen in one screenshot)

Files to Modify

  • crates/hero_slides/src/main.rs — suppress print_startup_info() for generate/content/theme/pdf subcommands
  • crates/hero_slides_server/src/generate_job.rs — verify legacy_logs_from_snapshot uses job_id, not run_id
  • crates/hero_slides_lib/src/generator.rs — add tracing::info! log line confirming which model was resolved (to make debugging easier going forward)

Implementation Plan

Step 1: Fix startup banner suppression

File: crates/hero_slides/src/main.rs

  • Find the print_startup_info() call
  • Move it inside the branch that handles --start / server startup only
  • For all generate, content, theme, pdf subcommands: skip the banner

Step 2: Fix log scoping in generate_job.rs

File: crates/hero_slides_server/src/generate_job.rs

  • Read legacy_logs_from_snapshot — confirm the hero_proc job.logs RPC call uses job_id
  • If it uses run_id or any aggregated scope, change it to scope by job_id only

Step 3: Add model logging in generator.rs

File: crates/hero_slides_lib/src/generator.rs

  • At the point where resolved_model / image_model is determined, add a tracing::info! or println! showing which model was selected for the slide
  • This surfaces model selection in the job logs without needing to read source code

Acceptance Criteria

  • hero_slides generate slide ... produces no banner lines in stdout
  • Job log modal shows only lines from that specific slide job, not from concurrent services
  • The JSON parse error "in response (line 22, position 5)" no longer occurs
  • Which AI model is being used is visible in the job logs
## Implementation Spec for Issue #68 ### Root Cause Analysis Three stacked problems were identified: **Problem 1: Startup banner pollutes job logs and causes JSON parse error** `hero_slides` calls `print_startup_info()` unconditionally on every invocation — including one-shot `generate slide` subcommands run by hero_proc. This prints a multi-line `===...===` banner to stdout before any valid log lines. Since hero_proc captures stdout as job log output, this banner becomes the first content in the log stream, causing the client-side JSON parser to fail with `"in response (line 22, position 5)"`. The fix is to suppress the banner for all non-server subcommands. **Problem 2: Job logs fetched by run_id instead of job_id (likely cause of aibroker log cross-contamination)** `legacy_logs_from_snapshot` in `generate_job.rs` fetches logs from hero_proc. If it passes `run_id` instead of `job_id`, hero_proc returns logs from *all* jobs in that run context — including concurrently-running services like hero_aibroker. This explains why aibroker startup messages (`aibroker.ui: Starting Hero AI Broker Admin`, `admin socket: ...`, multiple `scheduled job` entries) appear in slide generation job logs. **Problem 3: Slowness — model selection or missing API key** The AI call chain is correct: `hero_slides generate slide` → `AiClient::get()` → direct HTTP to OpenRouter (no agent subprocess, no CLI launch). The slowness is likely: - A per-slide `image_model` override set to the Pro model (Gemini Pro is 3-5x slower than Flash) - OR `OPENROUTER_API_KEY` missing from hero_proc secrets, causing `AiError::ModelNotAvailable` (explains the fast 3-line failure seen in one screenshot) ### Files to Modify - `crates/hero_slides/src/main.rs` — suppress `print_startup_info()` for generate/content/theme/pdf subcommands - `crates/hero_slides_server/src/generate_job.rs` — verify `legacy_logs_from_snapshot` uses `job_id`, not `run_id` - `crates/hero_slides_lib/src/generator.rs` — add `tracing::info!` log line confirming which model was resolved (to make debugging easier going forward) ### Implementation Plan #### Step 1: Fix startup banner suppression File: `crates/hero_slides/src/main.rs` - Find the `print_startup_info()` call - Move it inside the branch that handles `--start` / server startup only - For all `generate`, `content`, `theme`, `pdf` subcommands: skip the banner #### Step 2: Fix log scoping in generate_job.rs File: `crates/hero_slides_server/src/generate_job.rs` - Read `legacy_logs_from_snapshot` — confirm the hero_proc `job.logs` RPC call uses `job_id` - If it uses `run_id` or any aggregated scope, change it to scope by `job_id` only #### Step 3: Add model logging in generator.rs File: `crates/hero_slides_lib/src/generator.rs` - At the point where `resolved_model` / `image_model` is determined, add a `tracing::info!` or `println!` showing which model was selected for the slide - This surfaces model selection in the job logs without needing to read source code ### Acceptance Criteria - [ ] `hero_slides generate slide ...` produces no banner lines in stdout - [ ] Job log modal shows only lines from that specific slide job, not from concurrent services - [ ] The JSON parse error `"in response (line 22, position 5)"` no longer occurs - [ ] Which AI model is being used is visible in the job logs
Member

Test Results

  • Status: passed
  • Total: 156
  • Passed: 156
  • Failed: 0

All workspace tests pass (excluding hero_slides_examples which has a pre-existing compile error in its basic_usage example — missing tokio dependency).

Test breakdown by crate:

  • hero_slides_lib: 111 passed
  • hero_slides_server: 23 passed
  • hero_slides_rhai: 13 passed (1 ignored)
  • hero_slides_lib doc-tests: 2 passed
  • hero_slides_rhai doc-tests: 1 passed
  • hero_slides_sdk: 6 passed
## Test Results - Status: passed - Total: 156 - Passed: 156 - Failed: 0 All workspace tests pass (excluding `hero_slides_examples` which has a pre-existing compile error in its `basic_usage` example — missing `tokio` dependency). Test breakdown by crate: - hero_slides_lib: 111 passed - hero_slides_server: 23 passed - hero_slides_rhai: 13 passed (1 ignored) - hero_slides_lib doc-tests: 2 passed - hero_slides_rhai doc-tests: 1 passed - hero_slides_sdk: 6 passed
Member

Changes Applied

1. Startup banner suppressed for non-server invocations (crates/hero_slides/src/main.rs)

print_startup_info() was called unconditionally on every hero_slides invocation — including one-shot generate slide subcommands launched as hero_proc jobs. The banner printed a multi-line ===...=== block to stdout before any real log output, causing:

  • The JSON parse error "in response (line 22, position 5)" in the log modal (the parser choked on banner text before valid JSON)
  • Cosmetic noise in job log output

Fix: moved print_startup_info() inside the if cli.start branch. It now only prints when starting the server daemon. All other subcommands (generate, content, theme, pdf, etc.) produce clean stdout.

2. Log cross-contamination filter improved (crates/hero_slides_admin/static/js/dashboard.js)

The isLeakedLog() function previously only filtered JSON structured logs from other services. It did not filter plain-text startup banner lines from services like hero_aibroker — lines like type : admin, socket dir : ..., admin socket : ..., scheduled job — which were appearing in the slide generation log modal.

Extended the filter to also exclude:

  • Startup banner key-value lines (type : , socket dir : , admin socket : , openrpc : , sse : , web ui : )
  • Separator lines consisting only of = characters
  • scheduled job entries from hero_proc's scheduler
  • [INFO] service.sub: lines from services other than slides
  • Any line containing aibroker

3. Model selection already logged

Confirmed that generator.rs already logs model={} at info level for every slide generation, so the active model is visible in job logs without further changes.

Test Results

All 156 tests passed (0 failures) across hero_slides_lib, hero_slides_server, hero_slides_rhai, and hero_slides_sdk.

## Changes Applied ### 1. Startup banner suppressed for non-server invocations (`crates/hero_slides/src/main.rs`) `print_startup_info()` was called unconditionally on every `hero_slides` invocation — including one-shot `generate slide` subcommands launched as hero_proc jobs. The banner printed a multi-line `===...===` block to stdout before any real log output, causing: - The JSON parse error `"in response (line 22, position 5)"` in the log modal (the parser choked on banner text before valid JSON) - Cosmetic noise in job log output Fix: moved `print_startup_info()` inside the `if cli.start` branch. It now only prints when starting the server daemon. All other subcommands (`generate`, `content`, `theme`, `pdf`, etc.) produce clean stdout. ### 2. Log cross-contamination filter improved (`crates/hero_slides_admin/static/js/dashboard.js`) The `isLeakedLog()` function previously only filtered JSON structured logs from other services. It did not filter plain-text startup banner lines from services like `hero_aibroker` — lines like `type : admin`, `socket dir : ...`, `admin socket : ...`, `scheduled job` — which were appearing in the slide generation log modal. Extended the filter to also exclude: - Startup banner key-value lines (`type : `, `socket dir : `, `admin socket : `, `openrpc : `, `sse : `, `web ui : `) - Separator lines consisting only of `=` characters - `scheduled job` entries from hero_proc's scheduler - `[INFO] service.sub:` lines from services other than slides - Any line containing `aibroker` ### 3. Model selection already logged Confirmed that `generator.rs` already logs `model={}` at info level for every slide generation, so the active model is visible in job logs without further changes. ## Test Results All 156 tests passed (0 failures) across hero_slides_lib, hero_slides_server, hero_slides_rhai, and hero_slides_sdk.
Sign in to join this conversation.
No labels
No milestone
No project
No assignees
2 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
lhumina_code/hero_slides#68
No description provided.