🤖 *beep boop — clanker comment.* ## Context During [INC-13960](https://app.incident.io/gitlab/incidents/13960) (2026-09-08, saas-linux-small-amd64 Apdex SLO violation) VM creation on the docker+machine executor got two to three times slower from 14:10 UTC. `gitlab_runner_autoscaling_machine_creation_duration_seconds` showed p50 going from about 33s to 80 to 105s and p90 above 200s, but could not say where the time went or which VMs were affected. Reconstructing it from docker-machine log lines in Elasticsearch took about two hours: | Phase | Log boundaries | Normal | During incident | |---|---|---|---| | GCE insert | `Creating machine` → `bulkInsert placed as … in <zone>` | ~15s | 15–20s, never slowed | | Guest boot until sshd answers | `Waiting for SSH to be available` → `Detecting the provisioner` | 0–2s | p90 55–80s, worst 204s, us-east1-d only | | Provisioning | `Detecting the provisioner` → `Docker is up and running` | ~13s | unchanged | At the same time GCE stopped placing in us-east1-c, so most creations landed in the slow zone. ## The underlying gap docker-machine prints progress as free text on stdout. The runner reads it line by line and logs each line as a string. Everything above was recoverable only by matching English sentences and diffing timestamps by hand. The metrics side has the same shape: one number per create, no labels, buckets that start at 30s so every healthy create sits in the first two. Zone fallthrough is already visible: `gitlab_runner_autoscaling_actions_total{action="created"}` has had `target_zone` since 19.1, so `sum by (target_zone)` would have shown us-east1-c dropping out at 14:10. That needs a dashboard panel, not code. ## Plan ### Structured output from docker-machine https://gitlab.com/gitlab-org/ci-cd/docker-machine/-/merge_requests/193 - `--log-format=json` / `MACHINE_LOG_FORMAT=json`: one object per line with time, level, message and fields. - `log.WithField` / `log.WithFields`. Text output appends `key=value`, so nothing is lost when running by hand. - The first line of each create phase carries `phase` (certificate bootstrap, pre-create, driver create, wait for running, wait for SSH, OS detection, provisioning, Docker check). The variable parts of the create-path messages (zone, machine type, region, bulkInsert operation, attempt counters, provisioner) become fields. docker-machine measures nothing. Each line has a timestamp and the phase changes on the first line of the next one, so any consumer can diff. ### Runner consumes it https://gitlab.com/gitlab-org/gitlab-runner/-/merge_requests/7317 - `FF_DOCKER_MACHINE_JSON_OUTPUT`: the runner passes `--log-format=json` to `docker-machine create`, parses each line, and logs docker-machine's fields nested under `docker_machine` instead of as a string. Kibana can then filter on `docker_machine.phase` or `docker_machine.zone` directly. - `gitlab_runner_autoscaling_machine_creation_phase_duration_seconds{phase, result, target_*}` from the phase transitions. A phase still running when the runner kills the process on timeout is closed with the runner's clock, so a stuck SSH wait is attributed rather than lost. - Independent of the above: `target_*` labels on the creation and failed-creation histograms, and `[machine] creation_time_buckets` so the 30s floor can be lowered per installation. ## Follow-ups once the fields exist - Counter of bulkInsert attempts by machine type and outcome, from the `bulkInsert attempt` and stockout fallthrough lines. Shows a selection going out of stock before it shows up as creation failures. - The `retries` field on the runner's `Machine created` log line is the removal retry counter and is always 0 there. Remove or replace it. - Same treatment for the remaining `docker-machine` invocations (provision, rm, stop): pass the flag and parse, so all docker-machine output is structured, not only create. ## Evidence Sample slow VM (Chef `green-1`, project `gitlab-r-saas-l-s-amd64-1`), bulkInsert placed after 15s, then 3m36s waiting for SSH: ``` 14:38:35.314 Creating machine... 14:38:37.884 Waiting for bulkInsert operation operation-1788878315423-65af9b0898544-4e5b16ce-b51fbc1a 14:38:50.246 bulkInsert placed as n2d-standard-2 in us-east1-d 14:38:52.864 Waiting for SSH to be available... 14:42:28.435 Detecting the provisioner... 14:42:39.328 Docker is up and running! 14:42:39.331 Machine created ``` Per-zone SSH wait, all saas-linux-small-amd64 managers, 3-minute windows: | Window | us-east1-b | us-east1-c | us-east1-d | |---|---|---|---| | 14:00 | n=961, p90 2s | n=1168, p90 1s | n=5212, p50 1s / p90 3s | | 14:10 | n=256, p90 3s | n=29, p90 3s | n=5127, p50 12s / p90 68s | | 14:40 | n=47, p90 3s | n=7, p90 2s | n=2532, p50 51s / p90 72s | | 16:30 | n=1167, p90 3s | n=1327, p90 2s | n=5108, p50 2s / p90 62s |