Overview

When working with CircleCI, it can be crucial to know the exact timing of each command executed during your job. However, CircleCI's output does not display timestamps next to the line numbers, as it renders a fully "xterm" compatible terminal in the browser. This allows for features like colors and real-time progress bars, but it also means that lines can be updated dynamically, making it difficult to track when each command runs.

If you need to capture timing information during the execution of your commands, you can easily add your own code to print timestamps. Below are several methods to achieve this.

Method 1: Basic Timestamping

The simplest way to add timestamps is to insert commands at the start and end of your run steps to print out timestamps.

jobs:
  build:
    docker:
      - image: cimg/node:current
    steps:
      - checkout
      - run:
          name: "Download"
          command: |
            echo -n "started at "; date +"%Y-%m-%dT%H:%M:%S"
            wget https://example.com/some/really/big/file
            wget https://example.com/something/else/big
            echo -n "completed at "; date +"%Y-%m-%dT%H:%M:%S"
    

Limitations

• This method does not provide information on how long each command took to run.
• If a command fails, the "completed at" timestamp won't be printed.

Method 2: Advanced Timestamping with Custom Formatter

A more effective approach is to process the output of your commands as they execute, piping the output into a custom formatter that prepends a timestamp to each line.

- run:
    name: "Downloads"
    command: |
      bash -x -eo pipefail 2&1 \<< COMMANDS | my-custom-formatter
      wget https://example.com/some/really/big/file
      wget https://example.com/something/else/big
      COMMANDS
    

In this example, both STDOUT and STDERR from the commands are piped into my-custom-formatter. The -x option tells bash to print each command as it executes, allowing you to see when each command starts without waiting for it to finish.

Important Note

Use \<< instead of << to prevent CircleCI's pre-processor from misinterpreting the heredoc delimiter.

Method 3: Inline Custom Formatter

To avoid uploading a separate my-custom-formatter script, you can specify a small program inline for formatting. Here’s an example using Perl to print a yellow timestamp before each line and a final timestamp at the end:

- run:
    name: "Downloads"
    command: |
      bash -x -eo pipefail 2&1 \<< COMMANDS | perl -MTerm::ANSIColor=colored -MPOSIX=strftime -pE 'sub t(){colored(strftime(q!%FT%T !,gmtime),yellow)}s//t/e;END{say t.colored(Completed,red)}'
      wget https://example.com/some/really/big/file
      wget https://example.com/something/else/big
      COMMANDS
    

Method 4: Creating a Reusable Command

To keep your configuration clean and reduce redundancy, you can define a reusable command in your config file that wraps the run step with timestamp functionality:

commands:
  run-with-timings:
    parameters:
      command:
        type: string
      title:
        type: string
    steps:
        - run:
            name: "<< parameters.title >>"
            command: |
              bash -x -eo pipefail 2&1 \<< FEEA986F088E422E84246EE7BA862424 | perl -MTerm::ANSIColor=colored -MPOSIX=strftime -pE 'sub t(){colored(strftime(q!%FT%T !,gmtime),yellow)}s//t/e;END{say t.colored(Completed,red)}'
              << parameters.command >>
              FEEA986F088E422E84246EE7BA862424

jobs:
  build:
    docker:
      - image: cimg/node:current
    steps:
      - checkout
      - run-with-timings:
          title: "Testing"
          command: |
              wget https://example.com/some/really/big/file
              wget https://example.com/something/else/big
    

Note on Heredoc Terminator

In the example above, a fixed UUID is used as the heredoc terminator to ensure uniqueness and avoid accidental inclusion in the command.

Conclusion

By implementing these methods, you can effectively manage command output and timing in CircleCI, allowing for better tracking of your job executions. Once you've established a method that works for your needs, consider creating a private orb to share this functionality across your configuration files.