Tool call start time incorrectly reported?

Description

Running opencode 1.17.6, I am observing that the "timing" block reports and "start" and "end" times that have times that are way too close together. I used Codex + GPT-5.5 High to triage the problem and it suggests that there is a defect in how the "start" time is reset.

Plugins

None

OpenCode version

1.17.6

Steps to reproduce

Here is the opencode installed in the container:

[rabartl@8e6b72694d96 opencode (23574-fix-time-start)]$ which opencode
/usr/local/bin/opencode

[rabartl@8e6b72694d96 opencode (23574-fix-time-start)]$ opencode --version
1.17.6

I was able to reproduce this bug with:

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

with the reported time:

real    0m13.970s
user    0m3.516s
sys     0m0.675s

and the JSONL output:

{
  "type": "step_start",
  "timestamp": 1781623575133,
  "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
  "part": {
    "id": "prt_ed10a525b001rYLL0xCQ2JDp2a",
    "messageID": "msg_ed10a4eba001iJ8Ni2A0t3xjkT",
    "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
    "snapshot": "584a362a91a87499572288c55f3a1ca359f4e922",
    "type": "step-start"
  }
}
{
  "type": "tool_use",
  "timestamp": 1781623586512,
  "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
  "part": {
    "type": "tool",
    "tool": "bash",
    "callID": "XzxJgEoNyfQKisx1KqUQOrRdUsgmSFpC",
    "state": {
      "status": "completed",
      "input": {
        "command": "time sleep 10s",
        "description": "Run time sleep 10s",
        "timeout": 120000
      },
      "output": "\nreal\t0m10.001s\nuser\t0m0.000s\nsys\t0m0.001s\n",
      "metadata": {
        "output": "\nreal\t0m10.001s\nuser\t0m0.000s\nsys\t0m0.001s\n",
        "exit": 0,
        "description": "Run time sleep 10s",
        "truncated": false
      },
      "title": "Run time sleep 10s",
      "time": {
        "start": 1781623586506,
        "end": 1781623586510
      }
    },
    "id": "prt_ed10a5685001iR7Rz4rg9eRO2s",
    "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
    "messageID": "msg_ed10a4eba001iJ8Ni2A0t3xjkT"
  }
}
{
  "type": "step_finish",
  "timestamp": 1781623586532,
  "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
  "part": {
    "id": "prt_ed10a7ee1001xiTLlLhDpnKaVj",
    "reason": "tool-calls",
    "snapshot": "584a362a91a87499572288c55f3a1ca359f4e922",
    "messageID": "msg_ed10a4eba001iJ8Ni2A0t3xjkT",
    "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
    "type": "step-finish",
    "tokens": {
      "total": 8296,
      "input": 26,
      "output": 112,
      "reasoning": 0,
      "cache": {
        "write": 0,
        "read": 8158
      }
    },
    "cost": 0
  }
}
{
  "type": "step_start",
  "timestamp": 1781623586726,
  "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
  "part": {
    "id": "prt_ed10a7fa4001Q3IinvSH5FxjYT",
    "messageID": "msg_ed10a7ef7001MqJ2vUha3IZkzN",
    "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
    "snapshot": "584a362a91a87499572288c55f3a1ca359f4e922",
    "type": "step-start"
  }
}
{
  "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
    }
  }
}
{
  "type": "step_finish",
  "timestamp": 1781623587106,
  "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
  "part": {
    "id": "prt_ed10a811e001iXFMsTp92A878j",
    "reason": "stop",
    "snapshot": "584a362a91a87499572288c55f3a1ca359f4e922",
    "messageID": "msg_ed10a7ef7001MqJ2vUha3IZkzN",
    "sessionID": "ses_12ef5b29dffeNWj9H9elnMCmbv",
    "type": "step-finish",
    "tokens": {
      "total": 8384,
      "input": 83,
      "output": 41,
      "reasoning": 0,
      "cache": {
        "write": 0,
        "read": 8260
      }
    },
    "cost": 0
  }
}

That shows:

{
  "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
    }
  }
}

Okay, so the comamnd itself showed that it took over 10s but if you subtract the "start" and "end" you get
1781623587085 - 1781623586753 = 332 ms, or 0.332 seconds!

Screenshot and/or share link

Don't need a screenshot.

Operating System

This is in a RHEL9-based container:

& uname -r && cat /etc/os-release
6.14.0-37-generic
NAME="Red Hat Enterprise Linux"
VERSION="9.7 (Plow)"
ID="rhel"
ID_LIKE="fedora"
VERSION_ID="9.7"
PLATFORM_ID="platform:el9"
PRETTY_NAME="Red Hat Enterprise Linux 9.7 (Plow)"
ANSI_COLOR="0;31"
LOGO="fedora-logo-icon"
CPE_NAME="cpe:/o:redhat:enterprise_linux:9::baseos"
HOME_URL="https://www.redhat.com/"
DOCUMENTATION_URL="https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/9"
BUG_REPORT_URL="https://issues.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 9"
REDHAT_BUGZILLA_PRODUCT_VERSION=9.7
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="9.7"

Terminal

VS Code Terminal. (Otherwise, I would have to check.)

This issue doesn't fully meet our contributing guidelines.

What needs to be fixed:

Steps to reproduce is empty (placeholder text only: "ToDo: Fill in details")
Operating System is not filled in ("Ubuntu container ???" is not a real value)
Terminal is not filled in ("VS Code Terminal?" is uncertain placeholder text)
Description references an AI tool (Codex + GPT-5.5) for triaging but leaves the actual findings as a "ToDo" — please include the actual reproduction details yourself rather than delegating to AI output

Please edit this issue to address the above within 2 hours, or it will be automatically closed.

If you believe this was flagged incorrectly, please let a maintainer know.

Thanks for updating the issue! It now includes a clear description, reproduction steps with concrete output, version info, OS details, and terminal info. Everything looks good — the needs:compliance label has been removed.

I used Codex + GPT-5.5 to try to diagnose the problem. Here is what it came up with:

Yes, I think you found a real bug.

The intended start is set when the model’s tool call is registered: processor.ts (line 503). But then tool metadata updates overwrite it here: session/tools.ts (line 49).

That code does:

time: { start: Date.now() },

on every metadata update. The shell tool calls ctx.metadata(...) before spawning and again as output chunks arrive: shell.ts (line 482), shell.ts (line 534). So for a command that prints output near the end, start gets reset near completion, making end - start look impossibly short.

The likely fix is to preserve the existing running start time:

time: match.state.status === "running" ? match.state.time : { start: Date.now() },

in session/tools.ts (line 59).

Right now, from opencode run --format=json, I would not trust .part.state.time for bash commands that stream output. There is no separate reliable “start” event emitted by that JSON mode. The practical workaround is to time
inside the command itself with date/time until this is fixed.

This is the repo version:

25cb2be61 "fix(mcp): default tool schema properties (#32568)"
Author: Aiden Cline <[email protected]>
Date:   Tue Jun 16 10:27:20 2026 -0400 (44 minutes ago)

Here is the speculative fix:

fix: Speculative fix for incorrect time.start reset in tool call logging #32579

I have never worked with bun/JS/TS before but I can if that helps to get this fixed.

FYI: I took the time to build opencode locally with bun, add an automated test (that fails without the patch) and manually verified that this is now producing reasonable durations. See the new PR:

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

This is a clear defect. Please consider merging.

@kitlangton

@kitlangton, can you take a look?

To stay organized issues are automatically closed after 60 days of no activity. If the issue is still relevant please open a new one.

Still a problem. We are maintaining a fork of opencode to address this :-(

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

merged fix sorry :/ fell under the radar

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

Navigation Menu

Repository navigation

Tool call start time incorrectly reported? #32574

Description

Plugins

OpenCode version

Steps to reproduce

Screenshot and/or share link

Operating System

Terminal

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Tool call start time incorrectly reported? #32574

Description

Description

Plugins

OpenCode version

Steps to reproduce

Screenshot and/or share link

Operating System

Terminal

Activity

github-actions commented on Jun 16, 2026

github-actions commented on Jun 16, 2026

bartlettroscoe commented on Jun 16, 2026

bartlettroscoe commented on Jun 16, 2026

bartlettroscoe commented on Jun 16, 2026

bartlettroscoe commented on Jun 22, 2026

github-actions commented on Aug 26, 2026

bartlettroscoe commented on Aug 26, 2026

rekram1-node commented on Sep 2, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions