Skip to content

fix: improve Jev resolver timing and cost diagnostics - #16

Merged
MrGTV-love merged 8 commits into
mainfrom
fm/fm-jev-resolver-observability
Oct 5, 2026
Merged

MrGTV-love merged 8 commits into
mainfrom
fm/fm-jev-resolver-observability

Conversation

@MrGTV-love

@MrGTV-love MrGTV-love commented Oct 1, 2026 •

Copy link
Copy Markdown
Owner

Intent

do all of hte proposed fork fixes (2026-09-29, answering the Jev value report data/fm-jev-value-scout/report.md section 5, 'Fork follow-up shortlist'). Goal stated with it: "The user is looking to maximize performance while minimizing cost. Jev seems like a massive lever." Jev is typesafe.ai's System One model; firstmate calls it only from bin/fm-dispatch-resolve.sh (typed dispatch resolution). Work lands on the fork MrGTV-love/firstmate only; never push to, open, or comment on anything in kunchenguid/firstmate.

This task covers shortlist items 1 and 6:

  1. Fix stock macOS Bash timer precision (bin/fm-timing-lib.sh); log/API duration separately from quota snapshot and total run.
  2. Add resolver evidence/cost telemetry without logging secrets or raw sensitive brief text.

Report evidence: on macOS system Bash 3.2 (no EPOCHREALTIME) the resolver printed latency_ms: 0 for a ~211 ms API call and 1,000 ms elsewhere; the quota snapshot (~3.4-3.7 s), not Jev (~0.2 s), dominates the ~4 s resolver wall time.

I am concerned that prior evaluations of jev were not constructed properly (other models), so I would instruct the workstreams not to anchor on them

the Jev workstream is also important ... if we implement Jev, it could really helpful to our current work (improve speed, quality and reduce costs)

What Changed

  • Restore millisecond clock precision on stock macOS Bash and separate curl-reported API latency from quota snapshot, local processing, and total resolver time.
  • Report input/output token counts, estimated input-only Jev cost, and validated returned model versions; retain paid-call usage on quota failures and mark unavailable evidence as unknown.
  • Omit raw API error bodies and reject arbitrary model text from diagnostics to prevent sensitive-data leaks, with regression coverage and documentation for timing, cost, and privacy behavior.

Risk Assessment

✅ Low: The changes are bounded to diagnostic timing and cost evidence, preserve routing and shared epoch-clock compatibility, and apply the approved model-output privacy fix consistently without introducing a substantiated material defect.

Testing

The focused resolver behavior suite and live CLI scenarios passed using real curl, real quota-axi, Bash 3.2, and disposable Bash 5.3. Evidence shows separate API/quota/total timing, correct input-token cost, secret-safe model and error output, and preserved routing guards. The initial transport-adapter setup was corrected before successful validation. API responses were disposable fixtures, not a Jev-quality evaluation; all temporary setup was removed.

  • Live validation: ✅ go - 8 of 8 scenarios driven live against the product
Scenario Result Live Evidence
Resolve a brief on stock macOS Bash with separate timing and correct Jev cost ✅ pass live resolver-live-transcript.log: bash32-success-timing-cost
Use precise epoch clocks on Bash 3.2 without penalizing Bash 5 ✅ pass live clock-live-evidence.json
Resolve a brief when usage is absent or unsuitable for pricing ✅ pass live resolver-live-transcript.log: missing-usage-remains-unknown and invalid-numeric-usage-not-priced
Reject sensitive or malformed response-model text after successful quota processing ✅ pass live resolver-live-transcript.log: untrusted-model-success-1 through untrusted-model-success-5
Retain paid-call cost and safe model identity when quota processing fails ✅ pass live resolver-live-transcript.log: paid-call-retains-cost-on-real-quota-error and untrusted-model-quota-error
Handle HTTP errors, malformed responses, and network timeout without leaking sensitive text ✅ pass live resolver-live-transcript.log: http-error-redacts-raw-secret-body, malformed-success-response-redacts-sensitive-text, and actual-curl-timeout-keeps-intake-nonblocking
Preserve ambiguous and captain-approval routing while adding diagnostics ✅ pass live resolver-live-transcript.log: low-confidence-keeps-ambiguous-routing-with-telemetry and captain-approval-keeps-escalation-with-telemetry
Keep opt-out, never-send, and no-rules paths free of network and quota calls ✅ pass live resolver-live-transcript.log: absent-key-is-silent-and-makes-no-calls, never-send-still-blocks-before-network, and no-rules-keeps-minimal-output-without-telemetry
Evidence: Live resolver CLI transcripts and transport observations

Source: Live resolver CLI transcripts and transport observations

LIVE RESOLVER VALIDATION

{
  "product": "Unmodified bin/fm-dispatch-resolve.sh at target worktree; real Bash 3.2 and disposable source-built Bash 5.3",
  "transport": "Real /usr/bin/curl sends the unchanged HTTPS endpoint through --connect-to to a trusted local TLS fixture; adapter preserves fd 3. API responses are disposable test data, not live Jev inference.",
  "quota": "Real installed quota-axi consumes its supported QUOTA_AXI_SNAPSHOT cache-format fixture; snapshot mode never falls through to vendor credentials. Adapter adds 650ms only before non-version reads.",
  "synthetic_private_data": "Only synthetic key/private brief sentinels; actual operator state and credentials were not read.",
  "setup_corrections": [
    "Initial Python transport adapter did not preserve inherited fd 3; fixed pass_fds=(3,) before successful live drive.",
    "Cost assertion changed to numeric comparison because real CLI emits scientific notation.",
    "Perl execution detector checked by byte size, with a Bash 3.2 positive control."
  ],
  "assertions": "All recorded successful drives checked exit 0, secret omission, actual curl time_total/API-ms identity and latency alias, additive nonnegative stage accounting where both stages ran, and clean child environments."
}

=== bash32-success-timing-cost ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=2708
stdout:
dispatch-resolve:
  status: clear
  model: jev-1.13.0   latency_ms: 365   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.534  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1556834 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=365 quota_ms=1058 local_ms=1086 total_ms=2509
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.365457",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== missing-usage-remains-unknown ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=3289
stdout:
dispatch-resolve:
  status: clear
  model: jev-1.13.0   latency_ms: 363   tokens: -/-
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5337  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1557149 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=363 quota_ms=1742 local_ms=1034 total_ms=3139
  usage: input_tokens=null output_tokens=null jev_cost_usd=null jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.363991",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== invalid-numeric-usage-not-priced ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=2629
stdout:
dispatch-resolve:
  status: clear
  model: jev-1.13.0   latency_ms: 363   tokens: -1/2.5
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5337  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1557172 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=363 quota_ms=1250 local_ms=847 total_ms=2460
  usage: input_tokens=null output_tokens=null jev_cost_usd=null jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.363077",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== untrusted-model-success-1 ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=4067
stdout:
dispatch-resolve:
  status: clear
  model: -   latency_ms: 420   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5337  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1557210 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=420 quota_ms=1464 local_ms=2001 total_ms=3885
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=null

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.420113",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== untrusted-model-success-2 ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=3757
stdout:
dispatch-resolve:
  status: clear
  model: -   latency_ms: 380   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5336  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1557242 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=380 quota_ms=1892 local_ms=1385 total_ms=3657
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=null

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.380281",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== untrusted-model-success-

... [8051 bytes truncated] ...

resolve:
  status: error
  reason: http 000 after 5173 ms
  timings: api_ms=5173 quota_ms=null local_ms=717 total_ms=5890
  usage: input_tokens=null output_tokens=null jev_cost_usd=null jev_input_usd_per_million=0.042 returned_model=null

stderr:
dispatch-resolve: error (http 000 after 5173 ms)

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "000 5.173300",
      "rc": 28,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== low-confidence-keeps-ambiguous-routing-with-telemetry ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=5275
stdout:
dispatch-resolve:
  status: ambiguous
  model: jev-1.13.0   latency_ms: 397   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.5
  probabilities: rule_1=0.96 default=0.04
  reason: confidence 0.5 below floor 0.6
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5331  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1557848 projectionConfidence=early)]
  timings: api_ms=397 quota_ms=1908 local_ms=2094 total_ms=4399
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.397248",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== captain-approval-keeps-escalation-with-telemetry ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=2823
stdout:
dispatch-resolve:
  status: escalate
  model: jev-1.13.0   latency_ms: 352   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  reason: rule requires the captain's explicit approval before dispatch
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.533  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1557873 projectionConfidence=early)]
  timings: api_ms=352 quota_ms=1661 local_ms=744 total_ms=2757
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.352007",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== absent-key-is-silent-and-makes-no-calls ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=42
stdout:

stderr:
dispatch-resolve: off (TYPESAFE_API_KEY absent from the environment and ~/.no-mistakes/worktrees/32d18ed9638d/01M46EVPM60MRF5S8QWSEQD1ME/.live-resolver-2fqrwxc4/home/.env)

Actual curl/real quota observations:
{
  "curl": [],
  "quota_calls": [],
  "server_requests": []
}

=== never-send-still-blocks-before-network ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=370
stdout:

stderr:
dispatch-resolve: off (brief text matches ~/.no-mistakes/worktrees/32d18ed9638d/01M46EVPM60MRF5S8QWSEQD1ME/.live-resolver-2fqrwxc4/home/config/dispatch-never-send line 1; nothing sent)

Actual curl/real quota observations:
{
  "curl": [],
  "quota_calls": [],
  "server_requests": []
}

=== no-rules-keeps-minimal-output-without-telemetry ===
$ /bin/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=157
stdout:
dispatch-resolve:
  status: escalate
  reason: no rules to match

stderr:

Actual curl/real quota observations:
{
  "curl": [],
  "quota_calls": [],
  "server_requests": []
}

=== bash53-resolver-uses-no-perl ===
$ ~/.no-mistakes/worktrees/32d18ed9638d/01M46EVPM60MRF5S8QWSEQD1ME/.live-resolver-2fqrwxc4/bash-5.3/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=2326
stdout:
dispatch-resolve:
  status: clear
  model: jev-1.13.0   latency_ms: 379   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5323  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1558642 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=379 quota_ms=1305 local_ms=614 total_ms=2298
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.379660",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== bash53-full-resolver-no-perl-byte-proof ===
$ ~/.no-mistakes/worktrees/32d18ed9638d/01M46EVPM60MRF5S8QWSEQD1ME/.live-resolver-2fqrwxc4/bash-5.3/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation
exit=0 wall_ms=3277
stdout:
dispatch-resolve:
  status: clear
  model: jev-1.13.0   latency_ms: 369   tokens: 812/60
  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9
  probabilities: rule_1=0.96 default=0.04
  note: rule matched
  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5319  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1558935 projectionConfidence=early)]
  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'
  timings: api_ms=369 quota_ms=1490 local_ms=1356 total_ms=3215
  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=jev-1.13.0

stderr:

Actual curl/real quota observations:
{
  "curl": [
    {
      "write_out": "200 0.369312",
      "rc": 0,
      "key_on_argv": false,
      "secret_exported": false
    }
  ],
  "quota_calls": [
    "--version",
    "--json"
  ],
  "server_requests": [
    {
      "path": "/v1/systemone",
      "model": "jev-latest",
      "choices": [
        "default",
        "rule_1"
      ],
      "synthetic_authorization_received": true,
      "private_task_received": true
    }
  ]
}

=== Corrected fixture setup (not a product failure) ===
[
  "Initial Python transport adapter did not preserve inherited fd 3; fixed pass_fds=(3,) before successful live drive.",
  "Cost assertion changed to numeric comparison because real CLI emits scientific notation.",
  "Perl execution detector checked by byte size, with a Bash 3.2 positive control."
]
Evidence: Real Bash clock paths, shared epoch, and no-Perl evidence

Source: Real Bash clock paths, shared epoch, and no-Perl evidence

{
  "clock_runs": [
    {
      "shell": "/bin/bash",
      "rc": 0,
      "stdout": "bash=3.2.57(1)-release builtin_epoch=absent\nstart_ms=1791220724329 end_ms=1791220724627 elapsed_ms=298\nconvert_dot=211\nconvert_comma=211\nTIMINGS - where the deferred network checks spent their time (ms):\n  resolver    clock live                                 start=+16      elapsed=217\n  slowest: resolver clock live 217ms\n",
      "stderr": ""
    },
    {
      "shell": "~/.no-mistakes/worktrees/32d18ed9638d/01M46EVPM60MRF5S8QWSEQD1ME/.live-resolver-2fqrwxc4/bash-5.3/bash",
      "rc": 0,
      "stdout": "bash=5.3.0(1)-release builtin_epoch=1791220725.119055\nstart_ms=1791220725120 end_ms=1791220725402 elapsed_ms=282\nconvert_dot=211\nconvert_comma=211\nTIMINGS - where the deferred network checks spent their time (ms):\n  resolver    clock live                                 start=+2       elapsed=204\n  slowest: resolver clock live 204ms\n",
      "stderr": ""
    }
  ],
  "cross_shell": {
    "origin_ms": "1791220725640",
    "stdout": "TIMINGS - where the deferred network checks spent their time (ms):\n  resolver    cross-shell propagated                     start=+31      elapsed=231\n  slowest: resolver cross-shell propagated 231ms\n",
    "record": [
      "v1",
      "resolver",
      "cross-shell",
      "31",
      "231",
      "propagated"
    ],
    "rc": 0
  },
  "perl_execution_detector": {
    "bash53": {
      "stdout": "bash=5.3.0(1)-release builtin_epoch=1791220757.464710\n1791220757464\n1791220757464\n1791220757464\n",
      "rc": 0,
      "perl_log_bytes_before": 49,
      "perl_log_bytes_after": 49
    },
    "bash32_stamp": "1791220760858",
    "bytes_before_bash32": 49,
    "bytes_after_bash32": 56
  },
  "bash53_full_resolver": {
    "name": "bash53-full-resolver-no-perl-byte-proof",
    "command": "~/.no-mistakes/worktrees/32d18ed9638d/01M46EVPM60MRF5S8QWSEQD1ME/.live-resolver-2fqrwxc4/bash-5.3/bash bin/fm-dispatch-resolve.sh <disposable brief> --project isolated-live-validation",
    "rc": 0,
    "wall_ms": 3277,
    "stdout": "dispatch-resolve:\n  status: clear\n  model: jev-1.13.0   latency_ms: 369   tokens: 812/60\n  rule: rule_1 (Routine bug fix with known root cause)   confidence: 0.9\n  probabilities: rule_1=0.96 default=0.04\n  note: rule matched\n  candidate: cursor:cursor-grok-4.6-medium  provider=cursor  scope=all_models  remaining=90%  spendPriority=-0.5319  runway=projected_exhaustion  -> eligible [warning: projected_exhaustion at all_models (usableRunwaySeconds=1558935 projectionConfidence=early)]\n  profile: --harness 'cursor' --model 'cursor-grok-4.6-medium'\n  timings: api_ms=369 quota_ms=1490 local_ms=1356 total_ms=3215\n  usage: input_tokens=812 output_tokens=60 jev_cost_usd=3.4104e-05 jev_input_usd_per_million=0.042 returned_model=jev-1.13.0\n",
    "stderr": "",
    "curl": [
      {
        "write_out": "200 0.369312",
        "rc": 0,
        "key_on_argv": false,
        "secret_exported": false
      }
    ],
    "quota_calls": [
      "--version",
      "--json"
    ],
    "server_requests": [
      {
        "path": "/v1/systemone",
        "model": "jev-latest",
        "choices": [
          "default",
          "rule_1"
        ],
        "synthetic_authorization_received": true,
        "private_task_received": true
      }
    ],
    "perl_log_bytes_before": 49,
    "perl_log_bytes_after": 49
  }
}
Evidence: Real quota-axi output from disposable snapshot data

Source: Real quota-axi output from disposable snapshot data

{
  "generatedAt": "2026-10-05T17:13:37.333Z",
  "schemaVersion": 5,
  "providers": [
    {
      "provider": "claude",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "codex",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "cursor",
      "windows": [
        {
          "id": "included_usage",
          "label": "Monthly",
          "kind": "monthly",
          "percentRemaining": 90,
          "resetsAt": "2026-11-02T17:12:25.528070+00:00",
          "pace": {
            "status": "ahead",
            "reservePercentPoints": -3.3306,
            "burnMultiple": 1.4994
          }
        }
      ],
      "state": {
        "status": "fresh",
        "stale": false,
        "refreshedAt": "2026-10-05T17:12:25.528070+00:00",
        "reused": true
      },
      "quotaSemantics": {
        "status": "known",
        "effectiveAvailability": [
          {
            "scope": "all_models",
            "status": "known",
            "effectivePercentRemaining": 90,
            "boundedBy": [
              "included_usage"
            ],
            "limitingWindowIds": [
              "included_usage"
            ],
            "pace": {
              "status": "ahead",
              "aheadWindowIds": [
                "included_usage"
              ],
              "worstReservePercentPoints": -3.3306,
              "worstReserveWindowId": "included_usage"
            },
            "runway": {
              "status": "projected_exhaustion",
              "usableRunwaySeconds": 1555846,
              "projectedExhaustedAt": "2026-10-23T17:24:23.578Z",
              "limitingWindowId": "included_usage",
              "projectionConfidence": "early"
            },
            "selection": {
              "status": "known",
              "spendPriority": -0.5351
            }
          }
        ]
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "copilot",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": [],
        "unresolvedWindowIds": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "grok",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "kimi",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "zai",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "agy",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "alibaba",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "opencode-go",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": [],
        "unresolvedWindowIds": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "commandcode",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "minimax",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "mimo",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": [],
        "unresolvedWindowIds": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "deepseek",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": [],
        "unresolvedWindowIds": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "openrouter",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": [],
        "unresolvedWindowIds": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "elevenlabs",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "devin",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    },
    {
      "provider": "muse",
      "windows": [],
      "state": {
        "status": "unavailable",
        "stale": false,
        "error": "not_in_snapshot"
      },
      "quotaSemantics": {
        "status": "unknown",
        "effectiveAvailability": []
      },
      "accountKeys": [
        "default"
      ]
    }
  ]
}

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

✅ **Review** - passed

✅ No issues found.

✅ No issues found.

✅ **Test** - passed

✅ No issues found.

  • Live validation: ✅ go - 10 of 10 scenarios driven live against the product
Scenario Result Live Evidence
Resolve a brief on stock macOS Bash with separate API, quota, local, and total timing ✅ pass live resolver-live-transcript.txt: clear-timing-and-cost
Estimate Jev cost without inventing unavailable usage or charging output tokens ✅ pass live resolver-live-transcript.txt: clear-timing-and-cost, missing-usage-is-unknown, zero-input-output-free, negative-fractional-usage
Retain paid-call usage and returned Jev version when quota processing cannot proceed ✅ pass live resolver-live-transcript.txt: quota-failure-retains-paid-call, quota-unavailable-paid-call-preserved
Suppress hostile response model text on both successful and failed quota paths ✅ pass live resolver-live-transcript.txt: baseline reproduction, hostile-model-success-quota, hostile-model-failed-quota, model-object, model-number, model-alias, model-overlength
Handle HTTP and malformed-response failures without echoing sensitive API bodies ✅ pass live resolver-live-transcript.txt: sensitive-http-429, sensitive-http-500, sensitive-malformed-response
Report actual transport failure time while leaving unattempted telemetry unknown ✅ pass live resolver-live-transcript.txt: api-timeout-real-curl, api-connection-refused, curl-unavailable-api-time-unknown
Keep opt-out and never-send guards inert and protect request credential boundaries ✅ pass live resolver-live-transcript.txt: opt-out-sends-nothing, never-send-sensitive-brief, request and child-environment metadata
Record meaningful subsecond elapsed time on stock macOS Bash ✅ pass live timing-live.txt: STOCK_SHELL, RAW_PRODUCT_RECORDS, REAL_PRODUCT_RENDER, original-defect baseline
Use Bash 5's builtin clock without Perl and share an epoch origin with stock Bash ✅ pass live timing-live.txt: NEWER_SHELL and shared-origin records
Keep disabled recording inert and degrade safely when the high-resolution helper is unavailable ✅ pass live timing-live.txt: NORMAL_OFF_MODE and STOCK_PERL_UNAVAILABLE
  • /bin/bash tests/fm-dispatch-resolve.test.sh with inherited resolver/home overrides cleared and TMPDIR inside the disposable worktree setup; passed. Its Bash fast-path check skipped because PATH supplied Bash 3.2; the separate live Bash 5 check covered that path.
  • Executed /bin/bash bin/fm-dispatch-resolve.sh &lt;disposable brief&gt; --project disposable-resolver-validation across 20 isolated invocations using real curl, a disposable loopback HTTPS service, and real quota-axi with QUOTA_AXI_SNAPSHOT.
  • Compared emitted api_ms with real curl %{time_total}; checked latency alias, stage accounting, selected profile, input-only cost, returned model, request boundaries, and child-environment secret exclusion.
  • Drove missing, zero, negative, and fractional usage; failed and unavailable quota; hostile response models; HTTP 429/500; malformed responses; real timeout and connection refusal; unavailable curl; absent opt-in; and never-send suppression.
  • Executed disposable copies of the base-commit resolver and timing library against the same local services; reproduced sensitive model text in successful-quota output and latency_ms=0.
  • Downloaded official GNU Bash 5.2.37 into the worktree, built with ./configure --without-bash-malloc --disable-nls and make -j4, then exercised real timing helpers under Bash 3.2 and Bash 5.2.
  • Executed timing start/record/render with subsecond delays, shared cross-shell epoch origin, blocked Perl on the builtin path, unavailable Perl fallback, and disabled recording.
  • Saved CLI transcripts and structured runtime evidence; stopped the local HTTPS server and removed all disposable fixtures, downloaded source, and build outputs.

✅ No issues found.

  • Live validation: ✅ go - 8 of 8 scenarios driven live against the product
Scenario Result Live Evidence
Resolve a brief on stock macOS Bash with separate timing and correct Jev cost ✅ pass live resolver-live-transcript.log: bash32-success-timing-cost
Use precise epoch clocks on Bash 3.2 without penalizing Bash 5 ✅ pass live clock-live-evidence.json
Resolve a brief when usage is absent or unsuitable for pricing ✅ pass live resolver-live-transcript.log: missing-usage-remains-unknown and invalid-numeric-usage-not-priced
Reject sensitive or malformed response-model text after successful quota processing ✅ pass live resolver-live-transcript.log: untrusted-model-success-1 through untrusted-model-success-5
Retain paid-call cost and safe model identity when quota processing fails ✅ pass live resolver-live-transcript.log: paid-call-retains-cost-on-real-quota-error and untrusted-model-quota-error
Handle HTTP errors, malformed responses, and network timeout without leaking sensitive text ✅ pass live resolver-live-transcript.log: http-error-redacts-raw-secret-body, malformed-success-response-redacts-sensitive-text, and actual-curl-timeout-keeps-intake-nonblocking
Preserve ambiguous and captain-approval routing while adding diagnostics ✅ pass live resolver-live-transcript.log: low-confidence-keeps-ambiguous-routing-with-telemetry and captain-approval-keeps-escalation-with-telemetry
Keep opt-out, never-send, and no-rules paths free of network and quota calls ✅ pass live resolver-live-transcript.log: absent-key-is-silent-and-makes-no-calls, never-send-still-blocks-before-network, and no-rules-keeps-minimal-output-without-telemetry
  • /bin/bash tests/fm-dispatch-resolve.test.sh with isolated HOME and worktree-local TMPDIR — passed; its Bash-5-only check was covered separately using a disposable source-built Bash 5.3.
  • ./configure --without-bash-malloc --disable-nls &amp;&amp; make -j4 — built Bash 5.3 entirely inside the disposable worktree lab.
  • /bin/bash bin/fm-dispatch-resolve.sh &lt;disposable brief&gt; --project isolated-live-validation — drove the unchanged resolver through real curl against a local trusted TLS endpoint and real quota-axi against its supported QUOTA_AXI_SNAPSHOT fixture.
  • Exercised successful dispatch, missing and invalid usage, five adversarial response-model values, quota snapshot failure, HTTP 503 with sensitive response text, malformed HTTP-200 response, and an actual curl timeout.
  • Exercised low-confidence ambiguity, captain-approval escalation, absent-key silence, never-send rejection, and minimal no-rules output.
  • Executed the timing helpers under real Bash 3.2 and Bash 5.3; verified decimal conversion, shared epoch propagation, and no Perl execution across the complete Bash-5 resolver.
  • Published CLI transcripts, clock evidence, and actual quota-axi output; stopped the TLS fixture and removed the disposable lab, downloaded sources, build outputs, keys, configuration, and caches.
✅ **Document** - passed

✅ No issues found.

✅ No issues found.

✅ **Lint** - passed

✅ No issues found.

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

✅ No issues found.

@MrGTV-love
MrGTV-love force-pushed the fm/fm-jev-resolver-observability branch from 24eb33c to fbc86a8 Compare October 5, 2026 16:59
@MrGTV-love MrGTV-love changed the title fix(bin): give the dispatch resolver millisecond timing and safe Jev cost telemetry feat: add precise resolver timing and safe Jev cost telemetry Oct 5, 2026
…RESULT jq in bin/fm-dispatch-resolve.sh printed the raw response .model in the legacy `model:` line, so a crafted model string could print the key or brief text. The telemetry returned_model check did not cover that line. Fix: the numeric Jev model-ID check is now defined once, as JEV_MODEL_ID_JQ (def jev_model_id). Both jq programs use it: the telemetry usage line (returned_model) and the resolution result (model: ($r.model | jev_model_id)). Valid ids such as jev-1.13.0 still print. Unsafe ids print as `-` (unknown). Routing, usage, cost and exit codes do not change. Test: tests/fm-dispatch-resolve.test.sh has a new successful-quota case that reuses the sensitive-model fixture. I ran it before the fix and it failed: the `model:` line contained the key and private-brief-marker-4417. After the fix the full resolver suite passes, both with default bash and with RESOLVER_BASH=/bin/bash (Bash 3.2). The header comment, docs/configuration.md and docs/verification/dispatch-resolve.md now say the same thing. shellcheck reports only the old SC1091 info notes. tests/fm-lint.test.sh was still running when this result was due. Its finished cases all passed, and I saw no `not ok` lines, but I did not see the full run finish
@MrGTV-love
MrGTV-love force-pushed the fm/fm-jev-resolver-observability branch from fbc86a8 to e247ff7 Compare October 5, 2026 17:26
@MrGTV-love MrGTV-love changed the title feat: add precise resolver timing and safe Jev cost telemetry fix: improve Jev resolver timing and cost diagnostics Oct 5, 2026
@MrGTV-love
MrGTV-love merged commit 09acca7 into main Oct 5, 2026
22 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant