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.

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

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

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