Transforming GitHub Codespace Log Files to OpenTelemetry Traces

Recently I've had the requirement to track how long a GitHub codespace takes to start up.

Creation time is a key user happiness metric. If it takes 2 minutes to start today but 10 minutes next week, users will understandably be unhappy.

While the creation.log is available, interpreting it isn't exactly easy intuitive.

Example GitHub Codespace Creation Log

# /workspaces/.codespaces/.persistedshare/creation.log
2024-06-03 11:24:45.851Z: Host information
2024-06-03 11:24:45.894Z: ----------------
2024-06-03 11:24:45.938Z: OS: Ubuntu 22.04.4 LTS (stable release)
2024-06-03 11:24:45.942Z: Image details: https://github.com/github/codespaces-host-images/blob/main/README.md
2024-06-03 11:24:45.945Z: ----------------

=================================================================================
2024-06-03 11:24:45.950Z: Configuration starting...
2024-06-03 11:24:45.956Z: Cloning...
2024-06-03 11:24:45.969Z: $ git -C "/var/lib/docker/codespacemount/workspace" clone --branch "master" --depth 1 https://github.com/agardnerIT/someRepo "/var/lib/docker/codespacemount/workspace/someRepo"
2024-06-03 11:24:45.974Z: Cloning into '/var/lib/docker/codespacemount/workspace/someRepo'...
2024-06-03 11:24:49.237Z: git process exited with exit code 0
2024-06-03 11:24:49.244Z: $ git -C "/var/lib/docker/codespacemount/workspace/someRepo" config --local remote.origin.fetch +refs/heads/*:refs/remotes/origin/*
2024-06-03 11:24:49.250Z: git process exited with exit code 0
2024-06-03 11:24:49.348Z: Using image: mcr.microsoft.com/devcontainers/universal

=================================================================================
2024-06-03 11:24:49.377Z: Creating container...

=================================================================================
2024-06-03 11:24:50.086Z: Running blocking commands...
2024-06-03 11:24:50.165Z: $ devcontainer up --id-label Type=codespaces --workspace-folder /var/lib/docker/codespacemount/workspace/someRepo --mount type=bind,source=/.codespaces/agent/mount/cache,target=/vscode --user-data-folder /var/lib/docker/codespacemount/.persistedshare --container-data-folder .vscode-remote/data/Machine --container-system-data-folder /var/vscode-remote --log-level trace --log-format json --update-remote-user-uid-default never --mount-workspace-git-root false --omit-config-remote-env-from-metadata --skip-non-blocking-commands --expect-existing-container --override-config /root/.codespaces/shared/merged_devcontainer.json --default-user-env-probe loginInteractiveShell --container-session-data-folder /workspaces/.codespaces/.persistedshare/devcontainers-cli/cache --secrets-file /root/.codespaces/shared/user-secrets-envs.json
2024-06-03 11:24:50.409Z: @devcontainers/cli 0.56.1. Node.js v18.20.3. linux 6.5.0-1021-azure x64.
2024-06-03 11:24:50.650Z: Outcome: success User: codespace WorkspaceFolder: /workspaces/someRepo
2024-06-03 11:24:50.671Z: devcontainer process exited with exit code 0

=================================================================================
2024-06-03 11:24:50.722Z: Configuring codespace...
2024-06-03 11:24:50.783Z: Running oryx...
2024-06-03 11:24:50.849Z: $ python -m site --user-site
2024-06-03 11:24:51.626Z: /home/codespace/.local/lib/python3.10/site-packages
2024-06-03 11:24:51.648Z: python process exited with exit code 0
2024-06-03 11:24:51.683Z: $ python --version
2024-06-03 11:24:51.793Z: Python 3.10.13
2024-06-03 11:24:51.811Z: python process exited with exit code 0
2024-06-03 11:24:51.816Z: $ oryx build --manifest-dir "/workspaces/.oryx" --property packagedir="/home/codespace/.local/lib/python3.10/site-packages" --property python_version="3.10.13" --log-file "/workspaces/.oryx/build.log" "/workspaces/someRepo"
2024-06-03 11:24:54.430Z: Operation performed by Microsoft Oryx, https://github.com/Microsoft/Oryx
2024-06-03 11:24:54.434Z: You can report issues at https://github.com/Microsoft/Oryx/issues
2024-06-03 11:24:54.444Z: 
2024-06-03 11:24:54.449Z: Oryx Version: 0.2.0.0+c261287ed35c6c62b5ecf3174cda270495abb127, Commit: , ReleaseTagName: 
2024-06-03 11:24:54.480Z: 
2024-06-03 11:24:54.486Z: Build Operation ID: 347a9377dbcb21fe
2024-06-03 11:24:54.490Z: Repository Commit : 37b9b59dbe19bac41b714162afc38c11a091c1a0
2024-06-03 11:24:54.495Z: OS Type           : focal-scm
2024-06-03 11:24:54.502Z: Image Type        : vso-focal
2024-06-03 11:24:54.510Z: 
2024-06-03 11:24:54.522Z: Detecting platforms...
2024-06-03 11:24:54.699Z: Could not detect any platform in the source directory.
2024-06-03 11:24:54.744Z: Error: Could not detect the language from repo.
2024-06-03 11:24:54.805Z: oryx process exited with exit code 2
2024-06-03 11:24:54.829Z: $ cp -r /root/.docker /var/lib/docker/codespacemount/.persistedshare
2024-06-03 11:24:54.846Z: cp process exited with exit code 0
2024-06-03 11:24:54.862Z: $ rm -rf /home/codespace/.docker
2024-06-03 11:24:55.078Z: rm process exited with exit code 0
2024-06-03 11:24:55.088Z: $ ln -sfn /workspaces/.codespaces/.persistedshare/.docker /home/codespace/.docker
2024-06-03 11:24:55.243Z: ln process exited with exit code 0
2024-06-03 11:24:55.279Z: $ chown -R codespace /workspaces/.codespaces/.persistedshare/.docker
2024-06-03 11:24:55.392Z: chown process exited with exit code 0

=================================================================================
2024-06-03 11:24:55.403Z: Running commands...
2024-06-03 11:24:55.481Z: $ devcontainer up --id-label Type=codespaces --workspace-folder /var/lib/docker/codespacemount/workspace/someRepo --expect-existing-container --skip-post-attach --mount type=bind,source=/.codespaces/agent/mount/cache,target=/vscode --container-data-folder .vscode-remote/data/Machine --container-system-data-folder /var/vscode-remote --log-level trace --log-format json --update-remote-user-uid-default never --mount-workspace-git-root false --override-config /root/.codespaces/shared/merged_devcontainer.json --default-user-env-probe loginInteractiveShell --container-session-data-folder /workspaces/.codespaces/.persistedshare/devcontainers-cli/cache --secrets-file /root/.codespaces/shared/user-secrets-envs.json
2024-06-03 11:24:55.981Z: @devcontainers/cli 0.56.1. Node.js v18.20.3. linux 6.5.0-1021-azure x64.
2024-06-03 11:24:56.816Z: Running the postCreateCommand from Feature 'ghcr.io/devcontainers/features/git-lfs:1'...

2024-06-03 11:24:56.855Z: /usr/local/share/pull-git-lfs-artifacts.sh
2024-06-03 11:24:56.868Z: Fetching git lfs artifacts...
2024-06-03 11:24:57.953Z: devcontainer process exited with exit code 0
2024-06-03 11:24:57.968Z: Outcome: success User: codespace WorkspaceFolder: /workspaces/someRepo

=================================================================================
2024-06-03 11:24:58.206Z: Finished configuring codespace.

What I really need to see from this log, at a glance, is:

• The Configuration starting... step took 6 milliseconds
• The Cloning... step took 18 milliseconds
• The Cloning into '/var/lib/docker/codespacemount/workspace/site'... step took 3.4 seconds

Based on:

2024-06-03 11:24:45.950Z: Configuration starting...
2024-06-03 11:24:45.956Z: Cloning...
2024-06-03 11:24:45.974Z: Cloning into '/var/lib/docker/codespacemount/workspace/site'...
...
2024-06-03 11:24:49.377Z: Creating container...
...

Note: OTEL Collector Required

Tracepusher emits spans and expects a collector to be available as the endpoint, so you'll need to spin up a collector and expose the HTTP receiver (usually on port 4318).

Tracepusher to the Rescue

The first step is to ensure tracepusher binary is on the PATH so it can be called by the Python code we write.

Now:

• Generate trace id and span id for the "first" (parent) span
• Parse the log file to extract timings for each step (sub span)
• Send the main span with the timings corresponding to the entire end-to-end time
• Send a span for each step inside the log, also setting the trace id and parent span ID (so that your trace backend knows that all of these spans are related

Note: The final step (span) does not have an end time and thus the duration cannot be known, so just assume it lasted for 1 second:

trace_end_time = activity_start_left_dt + timedelta(seconds=1)

Put it all together

See Github Codespaces creation.log to OpenTelemetry code sample for the code.

Finally, trigger the script from devcontainer.json using the postCreateCommand:

{
   ...
  // Use 'postCreateCommand' to run commands after the container is created.
  "postCreateCommand": "python creation_log_parser.py",
}