Invalid log output duration

General
1

Hi,

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

image
image1316×227 31.7 KB

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]
    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
2

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 ?

3

Sure, I have added the date and time:

image

image
image1306×67 8.15 KB

image
image1306×157 18 KB

4

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

5

Hi,

You understood correctly the timestamp.

I’ve sent you an email as requested.