This bug has been migrated to another issue tracking site. It has been closed here and may no longer be being monitored.

If you would like to get updates for this issue, or to participate in it, you may do so at Red Hat Issue Tracker .
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2101763 - [RFE] Add realtime logs and enabling more verbosity for the image-creation process.
Summary: [RFE] Add realtime logs and enabling more verbosity for the image-creation pr...
Keywords:
Status: CLOSED MIGRATED
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: osbuild-composer
Version: 8.6
Hardware: All
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: Image Builder team
QA Contact: Release Test Team
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-06-28 10:36 UTC by Ameya Patil
Modified: 2023-10-09 11:48 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-10-09 11:48:02 UTC
Type: Story
Target Upstream Version:
Embargoed:
pm-rhel: mirror+

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker   RHEL-12246 0 None Migrated None 2023-10-09 11:47:54 UTC
Red Hat Issue Tracker RHELPLAN-126466 0 None None None 2022-06-28 10:47:49 UTC

Description Ameya Patil 2022-06-28 10:36:27 UTC 
Description of problem:

Image builder logs dont show timestamp value for the image creation process as well as the compose logs.
While troubleshooting an issue during the time of the image creation , there are no logs added to the journal by the osbuild-worker process.

Osbuild worker logs in the journal output show that the information below which is updated at "05:37" which is after the image creation completes, so its not real time and we dont have information about what the what its doing during these build process.

From the above logs we see that timing which is showing in the `time=` field are pretty much continuous across various build pipelines , and does not really show where the time is spent.
Due to this , while the image is being created if we issue like slow image creation or if it gets stuck on a particular stage, we dont have this infomation up until fully completes.

~~~
Jun 28 05:11:49 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:11:49-04:00" level=info msg="Running job 'b31928d3-0ca6-4ad3-adf8-1ae098308898' (osbuild)\n"
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="build pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.rpm success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.selinux success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="os pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.rpm success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.fix-bls success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.locale success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.timezone success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.sysconfig success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.selinux success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="anaconda-tree pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.rpm success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.buildstamp success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.locale success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.users success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.anaconda success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.lorax-script success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.dracut success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.selinux.config success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="bootiso-tree pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.bootiso.mono success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.kickstart success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.discinfo success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.tar success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="bootiso pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.xorrisofs success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="  org.osbuild.implantisomd5 success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:15 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:15-04:00" level=info msg="osbuild job succeeded" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:16 vm251-106.gsslab.pnq2.redhat.com osbuild-worker[1747]: time="2022-06-28T05:37:16-04:00" level=info msg="Job 'b31928d3-0ca6-4ad3-adf8-1ae098308898' (osbuild) finished"
~~~



The output which is generated by `# composer-cli compose log <UUID>` only generates a file at `logs/osbuild.log` and has most of the information about the packages but does not have timestamps or information about other stages.
~~~
Pipeline anaconda-tree
Stage org.osbuild.rpm
Output:
[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to resolve specifier: uninitialized /etc detected, skipping
All rules containing unresolvable specifiers will be skipped.
Failed to create file /sys/fs/selinux/checkreqprot: Read-only file system
imported gpg key
imported gpg key
creating a fake machine id
Verifying packages...
Preparing packages...
libgcc-8.5.0-10.el8.x86_64
fontpackages-filesystem-1.44-22.el8.noarch

[...output skipped...]

iwl6000-firmware-9.221.4.1-107.el8.1.noarch
libertas-usb8388-olpc-firmware-20220210-107.git6342082c.el8.noarch
dracut: No '/dev/log' or 'logger' included for syslog logging
dracut: No '/dev/log' or 'logger' included for syslog logging
deleting the fake machine id

Metadata:
{
  "packages": [
    {
      "name": "GConf2",
      "version": "3.2.6",
      "release": "22.el8",
      "epoch": null,
      "arch": "x86_64",
      "sigmd5": "f6b6d0d8d00c82d1f556425c2167c225",
      "sigpgp": "8902150305005c14238f199e2f91fd431d5101087a6d0fff61d1d4d47da75c73f605b99e1b196b12a59e5d02962a08c2ba78cfafdc1b4887882349ec1565225b1ab7f8d1fdc796f577891e4368232b84f5982e7dae172c484882b3c090063716cd
aa1ee0edb49312cde2811ce6dbfd2dc5dffc48e04a38a2b1dc641acf7d550b295184897a3fd08e170fa646f36f031280f84dd60ebb757611d402943671a0caedd7a6758efd61870b57e0114f5997073f69f24db6ad09dfe48cc151f1773f4d8fcf8e54f926b9194acc5
17157d55f28c7d3e948202641ef633e80ed70849daeedb1b60351c44c48dfd0a51150e2d35316ce3452f67dd14767be419e2b1e4901a5c1f8d7bc0a7ad109e3fe957fe8f6f730d082134a0b52aeff6f8ce1fde375fbb418feaf2db054667971f51d413b801ef8d2f434
55ff35e13ee0b188d5af2286526bf6d2c8255e4a396e898f50283712153ef3efbb823c543f48736010a9931209f79a81f6b20b6f5105ab7f23846c40f27220cae4fb8181b2969e0d02dcf9ccb2786e62ba9257c5c9a3b33c4d5260a648c3e2b5ec0dc0a13954248ae4a
7471ac8b32d2a5c5b53271fc561d40c0b01281ac6e0b054cdba9922eca3a6c0d6b6e3528c4c99086b598a50036da07032c8808a6e348fcdad5f7020a6c8f3f8df576c32739b2a3c4d721a948b63a40365737a3dfe3682831f44fc554d2e12b8ce679bf16cfb191b3fac
71bc9032625c23db843e12968d7d50dd2e",
      "siggpg": ""
    },
    {
      "name": "ModemManager-glib",

[...output skipped...]

038cfd6070b5a467735c362da600036b5df0fd5b5e5060e061ad6f9fe2482dfdb3c3ccbc5ffe3f3d0b914e0524be9b83e716bac0ba85e24429561614139bde878ef12ed3e58826bbb0e77bfdd1377b7866b76b22e70f95c2e317f448035ecc94f1b42c135bb6eb755538ef077099109c089e52f7387b80829d8e5f936265aa518ccea8bf99bf72f49d3fb3fa7fe8b9ab4eb6670686a306d3019a972680772428b48c18d687197e4175a48c98224a9a6ed1ac8ef32fe9ec0f408e5e82563578ca0662b7d61945bdd54025eb7ded746327cc825999de727482a901218a83aa7edf1eb88361",
      "siggpg": ""
    }
  ]
}

Stage org.osbuild.fix-bls
Output:
[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to resolve specifier: uninitialized /etc detected, skipping
All rules containing unresolvable specifiers will be skipped.
Failed to create file /sys/fs/selinux/checkreqprot: Read-only file system


Stage org.osbuild.locale
Output:
[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to resolve specifier: uninitialized /etc detected, skipping
All rules containing unresolvable specifiers will be skipped.
Failed to create file /sys/fs/selinux/checkreqprot: Read-only file system
/run/osbuild/tree/etc/locale.conf written.


Stage org.osbuild.timezone
Output:
[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to resolve specifier: uninitialized /etc detected, skipping
All rules containing unresolvable specifiers will be skipped.
Failed to create file /sys/fs/selinux/checkreqprot: Read-only file system
/etc/localtime already exists. Replacing.
/run/osbuild/tree/etc/localtime written


Stage org.osbuild.sysconfig
Output:
[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to resolve specifier: uninitialized /etc detected, skipping
All rules containing unresolvable specifiers will be skipped.
Failed to create file /sys/fs/selinux/checkreqprot: Read-only file system


Stage org.osbuild.selinux
Output:
[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to resolve specifier: uninitialized /etc detected, skipping
All rules containing unresolvable specifiers will be skipped.
Failed to create file /sys/fs/selinux/checkreqprot: Read-only file system
~~~


Version-Release number of selected component (if applicable):

cockpit-composer-36-1.el8.noarch
osbuild-53-2.el8.noarch
osbuild-composer-46.3-1.el8_6.x86_64
osbuild-composer-core-46.3-1.el8_6.x86_64
osbuild-composer-dnf-json-46.3-1.el8_6.x86_64
osbuild-composer-worker-46.3-1.el8_6.x86_64
osbuild-luks2-53-2.el8.noarch
osbuild-lvm2-53-2.el8.noarch
osbuild-ostree-53-2.el8.noarch
osbuild-selinux-53-2.el8.noarch
python3-osbuild-53-2.el8.noarch
weldr-client-35.5-1.el8.x86_64


How reproducible:
Every time


Steps to Reproduce:
1.  Create an image.

    # compose-cli compose start test-blueprint qcow2

2. Inspect the logs in the journal output for the osbuild-worker process which will be creating image.

    # journal -b -f -t osbuild-worker

3. After image creation see the logs generated by the compose-cli logs command. It only creates one output file in tar generated i.e. `logs/osbuild.log` 

    # composer-cli compose logs <UUID of the build>



Actual results:
Image builder does not show image logs in journal output in real time and only updates after the image-creation completes.
Also the logs are not verbose so if we get stuck on a particular stage we are NOT able to clearly determine what its doing during that time.
In addition, the log generated by `composer-cli compose logs <UUID>` dont have time stamp information and most of it contains information about packages and not other stages.

Expected results:
Adding real time logs to image build creation process and have then more verbose to see what it doing.
Add time stamps to the logs generated by `composer-cli compose logs <UUID>` and have more information about various stages it and be more verbose.


Additional info:

Raising this RFE as a part of the issue faced where the qcow2/vmdk creation takes 5 mins while the type `image-installer` takes around 20 mins to complete.
I will be raising seperate bug for this issue.
Comment 3 Sanne Raymaekers 2022-10-17 13:12:26 UTC 
This has been on our radar for a while, it would be nice to have. It would also make the timestamps a lot more useful, meaning we'd automatically get timing information as well.
Comment 5 RHEL Program Management 2023-10-09 11:45:37 UTC 
Issue migration from Bugzilla to Jira is in process at this time. This will be the last message in Jira copied from the Bugzilla bug.
Comment 6 RHEL Program Management 2023-10-09 11:48:02 UTC 
This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there.

Due to differences in account names between systems, some fields were not replicated.  Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information.

To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "RHEL-" followed by an integer.  You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like:

"Bugzilla Bug" = 1234567

In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information.
Note You need to log in before you can comment on or make changes to this bug.