# Invalid log output duration

**URL:** <https://forum.buildkite.community/t/invalid-log-output-duration/2127>\
**Category:** General\
**Created:** [July 5, 2022, 3:04pm UTC](https://forum.buildkite.community/t/invalid-log-output-duration/2127 "2022-07-05T15:04:59Z")\
**Posts on this page:** 5\
**Page:** 1

<div class="post-metadata">

**Author:** ![tetienne](https://avatars.discourse-cdn.com/v4/letter/t/ce73a5/32.png) [@tetienne](https://forum.buildkite.community/u/tetienne)\
**Post date:** [July 5, 2022, 3:04pm UTC](https://forum.buildkite.community/t/invalid-log-output-duration/2127/1 "2022-07-05T15:04:59Z")

</div>

Hi,

When using the log output group features, the displayed elapsed time is wrong:

 ![image](https://us1.discourse-cdn.com/flex016/uploads/buildkite1/original/2X/6/6bcbabc5428c498c83d894510c5c59180cbc725a.png)

As you can see, the 1st group is reported with a duration of 13m 25s while the 2nd group is reported with 5s. This obviously wrong. Should I change something in my configuration?

```auto
- label: ":rspec: Run tests"
    command: |
      echo "--- :database: Create and migrate database"
      bundle exec rails db:setup
      echo "--- :rspec: Run Rspec"
      bundle exec rake knapsack:rspec["--format progress --format RspecJunitFormatter --out reports/junit/junit-buildkite-job-$BUILDKITE_JOB_ID.xml]
    artifact_paths:
      - reports/**/*
    plugins:
      - docker-compose#v3.9.0:
          config: build/docker-compose.yml
          shell: ["/bin/bash", "-e", "-c"]
          workdir: /usr/src/app
          run: app
          volumes:
            - "./reports:/usr/src/app/reports"
          env:
            - BUILDKITE
            - BUILDKITE_BUILD_NUMBER
            - BUILDKITE_BUILD_URL
            - BUILDKITE_JOB_ID
            - BUILDKITE_BRANCH
            - BUILDKITE_COMMIT
            - BUILDKITE_MESSAGE
            - BUILDKITE_PARALLEL_JOB
            - BUILDKITE_PARALLEL_JOB_COUNT
            - KNAPSACK_GENERATE_REPORT=true

```

---

<div class="post-metadata">

**Author:** ![suma](https://sea2.discourse-cdn.com/flex016/user_avatar/forum.buildkite.community/suma/32/1306_2.png) [@suma](https://forum.buildkite.community/u/suma)\
**Post date:** [July 5, 2022, 8:05pm UTC](https://forum.buildkite.community/t/invalid-log-output-duration/2127/2 "2022-07-05T20:05:10Z")

</div>

Hi @tetienne

Reason you consider 1st group (bundle exec rails db:setup) reporting duration of 13m 25s is because it should not take that long for that step and 2nd group (bundle exec rake …) not to be done with in 5s ?

Just to be sure, would it be fine to echo time before each command so we can be certain how long the command took ?

---

<div class="post-metadata">

**Author:** ![tetienne](https://avatars.discourse-cdn.com/v4/letter/t/ce73a5/32.png) [@tetienne](https://forum.buildkite.community/u/tetienne)\
**Post date:** [July 6, 2022, 7:50am UTC](https://forum.buildkite.community/t/invalid-log-output-duration/2127/3 "2022-07-06T07:50:08Z")

</div>

Sure, I have added the date and time:

![image](https://us1.discourse-cdn.com/flex016/uploads/buildkite1/original/2X/2/2ba58f68f0bcc613ba72d68b38c6774cabd0a7ba.png)

 ![image](https://us1.discourse-cdn.com/flex016/uploads/buildkite1/original/2X/e/e0901c1b3db33983da748a47f173bf3000ca6604.png)

 ![image](https://us1.discourse-cdn.com/flex016/uploads/buildkite1/original/2X/2/258f0f60d9b324b93ba98299eae32c49bcd1ac30.png)

---

<div class="post-metadata">

**Author:** ![suma](https://sea2.discourse-cdn.com/flex016/user_avatar/forum.buildkite.community/suma/32/1306_2.png) [@suma](https://forum.buildkite.community/u/suma)\
**Post date:** [July 6, 2022, 6:08pm UTC](https://forum.buildkite.community/t/invalid-log-output-duration/2127/4 "2022-07-06T18:08:20Z")

</div>

@tetienne

Thank you for adding the date and time log messages for the commands.

So from first screenshot I see the timestamp as “July 6 07:32:16 UTC” which is under “Create and Migrate DB” command

Then second screenshot has timestamp as “July 6 07:32:31 UTC” which is under “Run Rspec” command

Can you explain what is the third screenshot which shows timestamp as “July 6 07:42:43 UTC” ? Is it when “Run Rspec” command completed ?

May be to speed up the things if you can send the pipeline and build url to [support@buildkite.com](mailto:support@buildkite.com) we can check these directly.

---

<div class="post-metadata">

**Author:** ![tetienne](https://avatars.discourse-cdn.com/v4/letter/t/ce73a5/32.png) [@tetienne](https://forum.buildkite.community/u/tetienne)\
**Post date:** [July 7, 2022, 10:15am UTC](https://forum.buildkite.community/t/invalid-log-output-duration/2127/5 "2022-07-07T10:15:31Z")

</div>

Hi,

You understood correctly the timestamp.

I’ve sent you an email as requested.