Transforming GitHub Codespace Log Files to OpenTelemetry Traces
Tags: github, opentelemetry, analytics, python
Published: 2024-06-09 00:32:12


![GitHub codespaces as traces in Jaeger](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/8vt67eyt7kg2sgp9z2kh.png)

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...
...
```

![trace in Jaeger](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/z7exl6fdcp0vymhxkgv4.png)

## 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](https://github.com/agardnerit/tracepusher/releases/latest) 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](https://github.com/agardnerIT/tracepusher/blob/main/samples/github_codespaces/creation_log_parser.py) 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",
}
```