Loading
Add JSON log format and create phase tagging
What
A JSON log format, selected with --log-format=json or MACHINE_LOG_FORMAT=json. Each line is one object with time, level and message plus any fields. Text stays the default and is unchanged.
Fields on log entries, through log.WithField and log.WithFields. The JSON format emits them as keys. The text format appends them as key=value.
A phase field on the first line of each create phase: certificate bootstrap, pre-create checks, the driver create call, waiting for the instance to run, waiting for SSH, OS detection, provisioning, and the Docker connection check. The variable parts of the create-path messages (provisioner, region, machine type, zone, bulkInsert operation, attempt counters) become fields instead of being formatted into the message.
Drivers run in a child process: docker-machine re-executes itself as a plugin server and talks to it over local RPC, an upstream design for third-party driver binaries that we keep only for uniformity. The driver's log lines come back over a pipe and are relayed through the parent's logger. The parent now passes its log format to the child (MACHINE_PLUGIN_LOG_FORMAT), and in JSON mode the relay parses the child's lines and re-logs them with their fields plus a machine field, instead of flattening them into (name) message. Running the one driver we use in-process would remove the child, the RPC hop and the relay; that is a separate change.
Why
During INC-13960 VM creation on the docker+machine executor got two to three times slower. The runner's creation histogram showed the slowdown. Finding out that the time went into the SSH wait, and only in one zone, took about two hours of comparing docker-machine log timestamps in Elasticsearch.
gitlab-runner already reads docker-machine's output line by line and logs each line. With JSON output it can log the fields as fields instead of as one string, and turn the phase changes into a per-phase duration histogram. docker-machine does not measure anything. Each line has a timestamp and the phase changes on the first line of the next one, so the runner can also account for a phase that was still running when it killed the process on timeout.
Runner side: gitlab-org/gitlab-runner!7317 (merged)
Edited by Igor