search

osbuild / osbuild-composer

An HTTP service for building bootable OS images.
https://www.osbuild.org
Apache License 2.0
156 stars 107 forks source link

lag between `composer-cli compose start` and command returning due preloading metadata of all repos #4212

Closed miabbott closed 3 weeks ago

miabbott commented 1 month ago

Describe the bug

When starting a compose that targets a specific distro, there is significant lag between the use of composer-cli compose start and the command returning, due to osbuild-composer preloading all of the supported repos. The time elapsed is around 3 minutes.

Environment

[core@localhost ~]$ cat /etc/os-release 
NAME="Red Hat Enterprise Linux"
VERSION="9.4 (Plow)"
ID="rhel"
ID_LIKE="fedora"
VERSION_ID="9.4"
PLATFORM_ID="platform:el9"
PRETTY_NAME="Red Hat Enterprise Linux 9.4 (Plow)"
ANSI_COLOR="0;31"
LOGO="fedora-logo-icon"
CPE_NAME="cpe:/o:redhat:enterprise_linux:9::baseos"
HOME_URL="https://www.redhat.com/"
DOCUMENTATION_URL="https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/9"
BUG_REPORT_URL="https://bugzilla.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 9"
REDHAT_BUGZILLA_PRODUCT_VERSION=9.4
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="9.4"
[core@localhost ~]$ cat /etc/redhat-release 
Red Hat Enterprise Linux release 9.4 (Plow)
$ rpm -qi osbuild-composer
Name        : osbuild-composer
Version     : 101
Release     : 1.el9
Architecture: x86_64
Install Date: Tue Jun 18 08:06:06 2024
Group       : Unspecified
Size        : 18399
License     : Apache-2.0
Signature   : RSA/SHA256, Tue Mar  5 05:12:56 2024, Key ID 199e2f91fd431d51
Source RPM  : osbuild-composer-101-1.el9.src.rpm
Build Date  : Mon Feb 26 07:26:12 2024
Build Host  : x86-64-05.build.eng.rdu2.redhat.com
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
Vendor      : Red Hat, Inc.
URL         : https://github.com/osbuild/osbuild-composer
Summary     : An image building service based on osbuild
Description :

A service for building customized OS artifacts, such as VM images and OSTree
commits, that uses osbuild under the hood. Besides building images for local
usage, it can also upload images directly to cloud.

It is compatible with composer-cli and cockpit-composer clients.

To Reproduce

  1. Install RHEL 9.4 host
  2. Register with subscription-manager
  3. Install osbuild bits
  4. Create simple blueprint that targets rhel-94
  5. Start edge-commit compose
  6. Observe lag between use of composer-cli compose start and the command returning

Expected behavior

The composer-cli compose start command should return quickly since only a single distro is being specified in the blueprint. Additionally, the CLI is just POST'ing to the API, so it should be able to fire and forget?

Additional context

Upon further investigation of the logs, it looks like osbuild-composer started the "preload goroutines" before the compose was started. It looks like this may have been a case of bad timing. But given that there is no output provided on the CLI after composer-cli compose start, it can be confusing to the user what is actually going on.

Relevant logs showing when the preload started, when the POST happened for a new compose, and when the next POST for the queue happened.

Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:08:37 Starting metadata preload goroutines
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: time="2024-06-18T08:08:37-04:00" level=warning msg="Sentry/Glitchtip not initialized, echo middleware was not enabled" func="github.com/osbuild/osbuild-composer/internal/cloudapi/v2.(*Server).Handler" file="/builddir/build/BUILD/osbuild-composer-101/_bui>
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: time="2024-06-18T08:08:37-04:00" level=info msg="Worker (x86_64) registered" func="github.com/osbuild/osbuild-composer/internal/worker.(*Server).RegisterWorker" file="/builddir/build/BUILD/osbuild-composer-101/_build/src/github.com/osbuild/osbuild-compos>
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:08:37 POST /api/v1/blueprints/new
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:37 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:08:55 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:08:55 Finished preload of rhel-9.2 in 18.353013939s
Jun 18 08:09:12 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:12 POST /api/v1/compose
Jun 18 08:09:12 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:09:12 localhost.localdomain osbuild-composer[31233]: Distro rhel-8-beta has repositories defined, but it's not supported. Skipping.
Jun 18 08:09:12 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:12 Please note that user customizations on "edge-commit" image type are deprecated and will be removed in the near future
Jun 18 08:09:16 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:16 Finished preload of rhel-9.4 in 38.69621956s
Jun 18 08:09:25 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:25 Finished preload of rhel-8 in 47.519430051s
Jun 18 08:09:28 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:28 Finished preload of rhel-9.1 in 50.882887415s
Jun 18 08:09:32 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:32 Finished preload of rhel-9.0 in 55.298201591s
Jun 18 08:09:50 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:50 Finished preload of rhel-9.3 in 1m13.037908874s
Jun 18 08:09:57 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:09:57 Finished preload of rhel-8.9 in 1m19.945445027s
Jun 18 08:10:17 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:10:17 Finished preload of rhel-9 in 1m40.125063939s
Jun 18 08:10:28 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:10:28 Finished preload of rhel-8.6 in 1m50.560688151s
Jun 18 08:10:54 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:10:54 Finished preload of rhel-8.7 in 2m16.986219263s
Jun 18 08:11:24 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:11:24 Finished preload of rhel-8.8 in 2m47.225307481s
Jun 18 08:11:38 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:11:38 Finished preload of rhel-8.5 in 3m1.494926916s
Jun 18 08:12:07 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:12:07 Finished preload of rhel-8.10 in 3m29.938202228s
Jun 18 08:12:23 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:12:23 Finished preload of rhel-8.4 in 3m46.190887797s
Jun 18 08:12:40 localhost.localdomain osbuild-composer[31233]: 2024/06/18 08:12:40 GET /api/v1/compose/queue
bcl commented 3 weeks ago

There's nothing you can do to speed this up other than maybe having a faster network connection. It needs the current metadata in order to correctly depsolve the blueprint so if you are starting osbuild-composer and immediately starting a build you just have to wait.

osbuild-composer does do a pre-load of the supported distros when it starts up though, so if you have an instance that is left running instead of starting it on demand it will seem faster the next time you start a build.

The reason why the cli waits is because the server runs a depsolve first, it is useful to know 'immediately' if the start command you just issued really started or if it failed because of a problem with the blueprint.