Invalid log output duration


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

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?

- 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]
      - reports/**/*
      - docker-compose#v3.9.0:
          config: build/docker-compose.yml
          shell: ["/bin/bash", "-e", "-c"]
          workdir: /usr/src/app
          run: app
            - "./reports:/usr/src/app/reports"
            - BUILDKITE
            - BUILDKITE_JOB_ID
            - BUILDKITE_BRANCH
            - BUILDKITE_COMMIT

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 ?

Sure, I have added the date and time:



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 we can check these directly.


You understood correctly the timestamp.

I’ve sent you an email as requested.