USHIFT-1465 Refactor prerun logs

[pmtk]

No description provided.

[dhellmann]

Nice polishing work. +1

[pmtk]

/test microshift-metal-tests

[ggiguash]

Do we want to put this in defer?

[pmtk]

I'm not rejecting the suggestions - if team members would find it more useful to use defers unconditionally on "end" messages and extend the "unit of work" logs to be more of "function scope", then we can do that.
But before we do this, I would recommend to take a look how the logs look like (sos from this PR's presubmits) because I was considering these defers (they might be even present in earlier commits), but I didn't like how the looked like in practice and, personally, I found them slightly confusing

[ggiguash]

This looks good to me. Holding off in case others would want to take a look.
/hold
/lgtm

[dhellmann]

Looks mostly good. I have a couple of thoughts inline, and 1 question about logging verbosity before we merge it.

[dhellmann]

If this produces a lot of data, we might want to consider not logging it ourselves and relying on sos to capture it instead. Let's keep it, and see how it goes.

[dhellmann]

I wonder each step here really needs to be a separate "unit of work". The whole function might be 1 unit doing the work of "checking upgrade compatibility" or something, from the user's perspective. If any of the internal steps is relatively slow, that could indicate that step should be a separate unit, but I think they're all pretty fast, right?

Let's keep this, but think more about where we draw the line about what a "unit" is and see if we can find the right balance.

[pmtk]

I'm wondering that myself, but given time constraints and feature being young, I'd rather have too verbose logs than not enough of them (and it's only about 60 lines)

[dhellmann]

How often are these messages going to show up? How often do we read that file?

[pmtk]

Once per boot MicroShift start

[pmtk]

Examples of version related logs

(I'm looking into data="<panic: value method github.com/openshift/microshift/pkg/admin/prerun.versionMetadata.String called using nil *versionMetadata pointer>")

version.go:31] "START version metadata management"
version.go:41] "START getting versions"
version.go:224] "START reading version file"
version.go:230] "END reading version file" contents={"version":"4.14.0","deployment_id":"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0","boot_id":"3492ff8831214dd7b7abb194e8fbf9fd"}
version.go:47] "END getting versions" exec="4.16.0" data="4.14.0"
version.go:52] "START version compatibility checks"
version.go:54] "FAIL version compatibility checks" err="executable (4.16.0) is too recent compared to existing data (4.14.0): version difference is 2, maximum allowed difference is 1"
version.go:33] "FAIL version metadata management" err="executable (4.16.0) is too recent compared to existing data (4.14.0): version difference is 2, maximum allowed difference is 1"
run.go:74] "command failed" err="executable (4.16.0) is too recent compared to existing data (4.14.0): version difference is 2, maximum allowed difference is 1"

-------------------------------------

version.go:31] "START version metadata management"
version.go:41] "START getting versions"
version.go:224] "START reading version file"
version.go:227] "FAIL reading version file" err="version file for MicroShift data does not exist"
version.go:114] "Version file does not exist yet - assuming first run of MicroShift"
version.go:47] "END getting versions" exec="4.14.0" data="<panic: value method github.com/openshift/microshift/pkg/admin/prerun.versionMetadata.String called using nil *versionMetadata pointer>"
version.go:50] "SKIP version compatibility checks - data does not exist"
version.go:67] "START updating version file"
system.go:44] "rpm-ostree status" output="{\"deployments\":[{\"unlocked\":\"none\",\"requested-local-packages\":[],\"base-commit-meta\":{\"ostree.linux\":\"5.14.0-284.25.1.el9_2.x86_64\",\"version\":\"9.2\",\"ostree.bootable\":true,\"rpmostree.inputhash\":\"ab4dab38eb70f2044b4f46d2af6820710c83dae0f7da3cb3d52689b2557ad239\"},\"base-removals\":[],\"requested-modules\":[],\"requested-modules-enabled\":[],\"pinned\":false,\"osname\":\"rhel\",\"base-remote-replacements\":{},\"origin\":\"edge:rhel-9.2-microshift-source-aux\",\"regenerate-initramfs\":false,\"checksum\":\"0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f\",\"gpg-enabled\":false,\"requested-base-local-replacements\":[],\"id\":\"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0\",\"version\":\"9.2\",\"requested-local-fileoverride-packages\":[],\"requested-base-removals\":[],\"modules\":[],\"requested-packages\":[],\"serial\":0,\"timestamp\":1692179923,\"staged\":false,\"booted\":true,\"packages\":[],\"base-local-replacements\":[]},{\"unlocked\":\"none\",\"requested-local-packages\":[],\"base-commit-meta\":{\"ostree.linux\":\"5.14.0-284.25.1.el9_2.x86_64\",\"version\":\"9.2\",\"ostree.bootable\":true,\"rpmostree.inputhash\":\"8eb75acb55ee951104556ea2b3696e0e3a4b79571debd318610ff2af84f0400d\"},\"base-removals\":[],\"requested-modules\":[],\"requested-modules-enabled\":[],\"pinned\":false,\"osname\":\"rhel\",\"base-remote-replacements\":{},\"origin\":\"edge:rhel-9.2\",\"regenerate-initramfs\":false,\"checksum\":\"58eefe3a542133210308e9fd8bcd91e946a159b4479cfa27c239ff969062b2b9\",\"gpg-enabled\":false,\"requested-base-local-replacements\":[],\"id\":\"rhel-58eefe3a542133210308e9fd8bcd91e946a159b4479cfa27c239ff969062b2b9.0\",\"version\":\"9.2\",\"requested-local-fileoverride-packages\":[],\"requested-base-removals\":[],\"modules\":[],\"requested-packages\":[],\"serial\":0,\"timestamp\":1692179172,\"staged\":false,\"booted\":false,\"packages\":[],\"base-local-replacements\":[]}],\"transaction\":null,\"cached-update\":null,\"update-driver\":null}"
system.go:58] "OSTree deployments" deployments=[{"id":"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0","booted":true,"staged":false,"pinned":false},{"id":"rhel-58eefe3a542133210308e9fd8bcd91e946a159b4479cfa27c239ff969062b2b9.0","booted":false,"staged":false,"pinned":false}]
version.go:149] "Version file contents to write" data={"version":"4.14.0","deployment_id":"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0","boot_id":"5888476c3d79406094ccaa98221f554c"}
version.go:72] "END updating version file"
version.go:36] "END version metadata management"

-------------------------------------

version.go:31] "START version metadata management"
version.go:41] "START getting versions"
version.go:224] "START reading version file"
version.go:230] "END reading version file" contents={"version":"4.14.0","deployment_id":"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0","boot_id":"d35956d20c4841c4aeae5584e2455109"}
version.go:47] "END getting versions" exec="4.15.0" data="4.14.0"
version.go:52] "START version compatibility checks"
version.go:293] "Executable is newer than data by 1 - continuing"
version.go:57] "END version compatibility checks"
version.go:59] "START checking if version upgrade is blocked"
upgrade_blocking.go:15] "START obtaining list of blocked upgrades"
upgrade_blocking.go:19] "SKIP obtaining list of blocked upgrades - embedded blocked upgrades asset does not exist - skipping check if upgrade is blocked"
version.go:64] "END checking if version upgrade is blocked"
version.go:67] "START updating version file"
system.go:44] "rpm-ostree status" output="{\"deployments\":[{\"unlocked\":\"none\",\"requested-local-packages\":[],\"base-commit-meta\":{\"ostree.linux\":\"5.14.0-284.25.1.el9_2.x86_64\",\"version\":\"9.2\",\"ostree.bootable\":true,\"rpmostree.inputhash\":\"4265fd16f3826fa5728fbaa4d946b5b6b725d1a3e1b9fb279fd6e8bf38b4bead\"},\"base-removals\":[],\"requested-modules\":[],\"requested-modules-enabled\":[],\"pinned\":false,\"osname\":\"rhel\",\"base-remote-replacements\":{},\"origin\":\"edge:rhel-9.2-microshift-source-fake-next-minor\",\"regenerate-initramfs\":false,\"checksum\":\"050c3f774bbd04af950ea9a35f20c758e6ce17d484eb7bde8977536ea8ccf3a1\",\"gpg-enabled\":false,\"requested-base-local-replacements\":[],\"id\":\"rhel-050c3f774bbd04af950ea9a35f20c758e6ce17d484eb7bde8977536ea8ccf3a1.0\",\"version\":\"9.2\",\"requested-local-fileoverride-packages\":[],\"requested-base-removals\":[],\"modules\":[],\"requested-packages\":[],\"serial\":0,\"timestamp\":1692179927,\"staged\":false,\"booted\":true,\"packages\":[],\"base-local-replacements\":[]},{\"unlocked\":\"none\",\"requested-local-packages\":[],\"base-commit-meta\":{\"ostree.linux\":\"5.14.0-284.25.1.el9_2.x86_64\",\"version\":\"9.2\",\"ostree.bootable\":true,\"rpmostree.inputhash\":\"ab4dab38eb70f2044b4f46d2af6820710c83dae0f7da3cb3d52689b2557ad239\"},\"base-removals\":[],\"requested-modules\":[],\"requested-modules-enabled\":[],\"pinned\":false,\"osname\":\"rhel\",\"base-remote-replacements\":{},\"origin\":\"edge:rhel-9.2-microshift-source\",\"regenerate-initramfs\":false,\"checksum\":\"0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f\",\"gpg-enabled\":false,\"requested-base-local-replacements\":[],\"id\":\"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0\",\"version\":\"9.2\",\"requested-local-fileoverride-packages\":[],\"requested-base-removals\":[],\"modules\":[],\"requested-packages\":[],\"serial\":0,\"timestamp\":1692179923,\"staged\":false,\"booted\":false,\"packages\":[],\"base-local-replacements\":[]}],\"transaction\":null,\"cached-update\":null,\"update-driver\":null}"
system.go:58] "OSTree deployments" deployments=[{"id":"rhel-050c3f774bbd04af950ea9a35f20c758e6ce17d484eb7bde8977536ea8ccf3a1.0","booted":true,"staged":false,"pinned":false},{"id":"rhel-0ec8dadbb2a1137c74b5557e3e51a7a8fc85c9b134092c7d3378b3cf1c9f711f.0","booted":false,"staged":false,"pinned":false}]
version.go:149] "Version file contents to write" data={"version":"4.15.0","deployment_id":"rhel-050c3f774bbd04af950ea9a35f20c758e6ce17d484eb7bde8977536ea8ccf3a1.0","boot_id":"1e6ea2d44b324374bc4113ed8af723b8"}
version.go:72] "END updating version file"
version.go:36] "END version metadata management"

[pmtk]

/test microshift-e2e-arm

[openshift-ci]

@pmtk: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
ci/prow/e2e-openshift-conformance-reduced-arm	e296eee	link	false	/test e2e-openshift-conformance-reduced-arm
ci/prow/e2e-openshift-conformance-reduced	e296eee	link	false	/test e2e-openshift-conformance-reduced

Full PR test history. Your PR dashboard.

Details

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

[pmtk]

/unhold

[ggiguash]

/lgtm

[pmtk]

/hold

[openshift-ci]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: ggiguash, pmtk

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details

Needs approval from an approver in each of these files:

• OWNERS [ggiguash,pmtk]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[pmtk]

/unhold