fix(core): Fix for incorrect time.start reset in tool call logging (#32574)

[bartlettroscoe]

Description

New test fails if you don't have this fix.

Issue for this PR

Closes #32574

Type of change

• Bug fix
• New feature
• Refactor / code improvement
• Documentation

What does this PR do?

Fixes the "start" time in the "time" block for json tool calling output so it produces the right start time and time difference.

Before this fix, running:

time opencode run --format=json "Run the comamnd 'time sleep 10s' and report what it shows" | jq

produced a JSON dict like:

{
  "type": "text",
  "timestamp": 1781623587086,
  "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
  "part": {
    "id": "prt_ed10a7fc1001cnEl1E5FBGo5IC",
    "messageID": "msg_ed10a7ef7001MqJ2vUha3IZkzN",
    "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
    "type": "text",
    "text": "The command produced the following output:\n\n```\nreal\t0m10.001s\nuser\t0m0.000s\nsys\t0m0.001s\n```",
    "time": {
      "start": 1781623586753,
      "end": 1781623587085
    }
  }
}

where 1781623587085 - 1781623586753 = 332 ms, or 0.332 sec and is clearly not anywhere close to 10 seconds.

After the fix in this PR, the local build of of opencode produces something like:

{
  "type": "text",
  "timestamp": 1781635217752,
  "sessionID": "ses_12e44bf64ffer14wSI0QfvgZtj",
  "part": {
    "id": "prt_ed1bbd3c9001Iv3RErkj2zz4dz",
    "messageID": "msg_ed1bbc128001JABc8U374fps3W",
    "sessionID": "ses_12e44bf64ffer14wSI0QfvgZtj",
    "type": "text",
    "text": "The command took approximately 10 seconds to complete:\n\n```\nreal\t0m10.001s\nuser\t0m0.000s\nsys\t0m0.001s\n```\n\n- **real**: Total elapsed time (10.001s)\n- **user**: CPU time in user mode (negligible)\n- **sys**: CPU time in kernel mode (negligible)",
    "time": {
      "start": 1781635208137,
      "end": 1781635217750
    }
  }
}

where 1781635217750 - 1781635208137 = 9613 ms = 9.613 sec is close enough to 10.0 sec.

How did you verify your code works?

I added a new unit test in this PR that fails without the patch and passed with the patch.

I also built and run the binary locally with:

time /mounted_from_host/PROJECTS/opencode/packages/opencode/dist/opencode-linux-x64/bin/opencode \
  run --format=json --model opencode/nemotron-3-ultra-free \
  "Run the comamnd 'time sleep 10s' and report what it shows" | jq

and verified that it gave a reasonable timing for a command that should take 10 sec. The above produced:

{
  "type": "text",
  "timestamp": 1781635217752,
  "sessionID": "ses_12e44bf64ffer14wSI0QfvgZtj",
  "part": {
    "id": "prt_ed1bbd3c9001Iv3RErkj2zz4dz",
    "messageID": "msg_ed1bbc128001JABc8U374fps3W",
    "sessionID": "ses_12e44bf64ffer14wSI0QfvgZtj",
    "type": "text",
    "text": "The command took approximately 10 seconds to complete:\n\n```\nreal\t0m10.001s\nuser\t0m0.000s\nsys\t0m0.001s\n```\n\n- **real**: Total elapsed time (10.001s)\n- **user**: CPU time in user mode (negligible)\n- **sys**: CPU time in kernel mode (negligible)",
    "time": {
      "start": 1781635208137,
      "end": 1781635217750
    }
  }
}

where 1781635217750 - 1781635208137 = 9613 ms = 9.613 sec is close enough to 10.0 sec.

Screenshots / recordings

I don't have any screenshots. They are not needed. The above is enough to fully expose the defect and demonstrate the fix.

If this is a UI change, please include a screenshot or recording.

Checklist

• I have tested my changes locally
• I have not included unrelated changes in this PR

If you do not follow this template your PR will be automatically rejected.

[bartlettroscoe]

FYI: The GHA failures shown at:

• https://github.com/anomalyco/opencode/actions/runs/27629701573
• https://github.com/anomalyco/opencode/actions/runs/27629701573/job/81711009423

don't seem to be related to the code changes I made. I added the new test:

• packages/opencode/test/session/tools.test.ts

The failing tests seem to be in:

• opencode/opencode/packages/opencode/test/cli/cmd/tui/attention.test.ts

and the final error looks like:

...
opencode:test: failed to load attention sound {
opencode:test:   file: "/home/runner/_work/opencode/opencode/packages/ui/src/assets/audio/bip-bop-01.mp3",
opencode:test:   error: 53 |   rejectPaths = new Set<string>()
opencode:test: 54 | 
opencode:test: 55 |   async loadSoundFile(path: string) {
opencode:test: 56 |     this.loadCalls += 1
opencode:test: 57 |     this.loadPaths.push(path)
opencode:test: 58 |     if (this.rejectLoad || this.rejectPaths.has(path)) throw new Error("decode failed")
opencode:test:                                                                       ^
opencode:test: error: decode failed
opencode:test:       at loadSoundFile (/home/runner/_work/opencode/opencode/packages/opencode/test/cli/cmd/tui/attention.test.ts:58:66)
opencode:test:       at playSound (/home/runner/_work/opencode/opencode/packages/tui/src/attention.ts:154:37)
opencode:test:       at notify (/home/runner/_work/opencode/opencode/packages/tui/src/attention.ts:200:73)
opencode:test:       at <anonymous> (/home/runner/_work/opencode/opencode/packages/opencode/test/cli/cmd/tui/attention.test.ts:441:28)
opencode:test: ,
opencode:test: }
opencode:test: 
opencode:test: ::endgroup::
opencode:test: 
opencode:test:  2982 pass
opencode:test:  22 skip
opencode:test:  1 todo
opencode:test:  1 fail
opencode:test:  50 snapshots, 8024 expect() calls
opencode:test: Ran 3006 tests across 243 files. [442.62s]
opencode:test: error: script "test" exited with code 1

 Tasks:    5 successful, 6 total
Cached:    0 cached, 6 total
  Time:    7m29.323s 
Failed:    opencode#test

Looks like we see the same errors in other GHA builds for other PRs like:

• https://github.com/anomalyco/opencode/actions/runs/27656286792/job/81791118174

showing the same error output:

opencode:test: failed to load attention sound {
opencode:test:   file: "/home/runner/_work/opencode/opencode/packages/ui/src/assets/audio/bip-bop-01.mp3",
opencode:test:   error: 53 |   rejectPaths = new Set<string>()
opencode:test: 54 | 
opencode:test: 55 |   async loadSoundFile(path: string) {
opencode:test: 56 |     this.loadCalls += 1
opencode:test: 57 |     this.loadPaths.push(path)
opencode:test: 58 |     if (this.rejectLoad || this.rejectPaths.has(path)) throw new Error("decode failed")
opencode:test:                                                                       ^
opencode:test: error: decode failed
opencode:test:       at loadSoundFile (/home/runner/_work/opencode/opencode/packages/opencode/test/cli/cmd/tui/attention.test.ts:58:66)
opencode:test:       at playSound (/home/runner/_work/opencode/opencode/packages/tui/src/attention.ts:154:37)
opencode:test:       at notify (/home/runner/_work/opencode/opencode/packages/tui/src/attention.ts:200:73)
opencode:test:       at <anonymous> (/home/runner/_work/opencode/opencode/packages/opencode/test/cli/cmd/tui/attention.test.ts:441:28)
opencode:test: ,
opencode:test: }
opencode:test: 
opencode:test: ::endgroup::
opencode:test: 
opencode:test:  2988 pass
opencode:test:  22 skip
opencode:test:  1 todo
opencode:test:  1 fail
opencode:test:  50 snapshots, 8025 expect() calls
opencode:test: Ran 3012 tests across 243 files. [284.16s]
opencode:test: error: script "test" exited with code 1

 Tasks:    5 successful, 6 total
Cached:    0 cached, 6 total
  Time:    4m49.749s 
Failed:    opencode#test

error: "turbo" exited with code 1

What is the chance that two different random PRs from different developers are triggering the same errors?

Me thinks the test suite for opencode is broken on dev. This may be a random error but it does not seem to be related to the changes in the PR.

Detecting problems with the test suite seems like a good task for an AI agent!

[bartlettroscoe]

@kitlangton, can you take a look as part of #32574?