OCPBUGS-50476: v2/cli: always stop local registry and close registry.log #1068

r4f4 · 2025-02-05T23:46:23Z

Description

The local registry was not being gracefully shutdown and in some cases the registry.log file was closed while logrus was still trying to write to it:

2025/02/05 21:50:45  [INFO]   : mirror time     : 29.768175677s
2025/02/05 21:50:45  [INFO]   : 👋 Goodbye, thank you for using oc-mirror
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed

Github / Jira issue:

Type of change

Please delete options that are not relevant.

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
Code Improvements (Refactoring, Performance, CI upgrades, etc)
Internal repo assets (diagrams / docs on github repo)
This change requires a documentation update on openshift docs

How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Provide instructions so we can reproduce. Please also list any relevant details for your test configuration.

Expected Outcome

Please describe the outcome expected from the tests.

openshift-ci · 2025-02-05T23:46:45Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: r4f4
Once this PR has been reviewed and has the lgtm label, please assign aguidirh for approval. For more information see the Code Review Process.

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

Needs approval from an approver in each of these files:

OWNERS

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

lmzuccarelli · 2025-02-06T08:12:50Z

v2/internal/pkg/cli/executor.go

+	if o.registryLogFile != nil {
+		// NOTE: we cannot just close the registry.log file as it is set as logrus output, which could still be in use
+		// by other dependencies before we exit. First we need to make sure logrus uses a different output.
+		logrus.SetOutput(io.Discard)


@r4f4 - good one, this has been a lingering problem

lmzuccarelli · 2025-02-06T08:15:19Z

@r4f4 - Thanks for this update, improves our user experience and proper shutdown of the local registry and logs

The local registry was not being gracefully shutdown and in some cases the `registry.log` file was closed while `logrus` was still trying to write to it: ``` 2025/02/05 21:50:45 [INFO] : mirror time : 29.768175677s 2025/02/05 21:50:45 [INFO] : 👋 Goodbye, thank you for using oc-mirror Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed ```

r4f4 · 2025-02-06T08:52:27Z

Update: fixed unit tests.

r4f4 · 2025-02-09T11:34:25Z

/retitle OCPBUGS-50476: v2/cli: always stop local registry and close registry.log

openshift-ci-robot · 2025-02-09T11:34:32Z

@r4f4: This pull request references Jira Issue OCPBUGS-50476, which is invalid:

expected the bug to target the "4.19.0" version, but no target version was set

Comment /jira refresh to re-evaluate validity if changes to the Jira bug are made, or edit the title of this pull request to link to a different bug.

The bug has been updated to refer to the pull request using the external bug tracker.

In response to this:

Description

The local registry was not being gracefully shutdown and in some cases the registry.log file was closed while logrus was still trying to write to it:
2025/02/05 21:50:45  [INFO]   : mirror time     : 29.768175677s
2025/02/05 21:50:45  [INFO]   : 👋 Goodbye, thank you for using oc-mirror
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Failed to write to log, write /oc-mirror-issue-ret/working-dir/logs/registry.log: file already closed
Github / Jira issue:

Type of change

Please delete options that are not relevant.

Bug fix (non-breaking change which fixes an issue)

New feature (non-breaking change which adds functionality)

Breaking change (fix or feature that would cause existing functionality to not work as expected)

Code Improvements (Refactoring, Performance, CI upgrades, etc)

Internal repo assets (diagrams / docs on github repo)

This change requires a documentation update on openshift docs

How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Provide instructions so we can reproduce. Please also list any relevant details for your test configuration.

Expected Outcome

Please describe the outcome expected from the tests.

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 openshift-eng/jira-lifecycle-plugin repository.

r4f4 · 2025-02-09T11:35:56Z

/jira refresh

openshift-ci-robot · 2025-02-09T11:36:02Z

@r4f4: This pull request references Jira Issue OCPBUGS-50476, which is valid. The bug has been moved to the POST state.

3 validation(s) were run on this bug

bug is open, matching expected state (open)
bug target version (4.19.0) matches configured target version for branch (4.19.0)
bug is in the state New, which is one of the valid states (NEW, ASSIGNED, POST)

Requesting review from QA contact:
/cc @zhouying7780

In response to this:

/jira refresh

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 openshift-eng/jira-lifecycle-plugin repository.

r4f4 · 2025-02-09T11:36:19Z

/test e2e

openshift-ci · 2025-02-09T11:56:26Z

@r4f4: all tests passed!

Full PR test history. Your PR dashboard.

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-sigs/prow repository. I understand the commands that are listed here.

lmzuccarelli · 2025-02-10T08:21:13Z

v2/internal/pkg/cli/executor.go

+// stopLocalRegistry - stops the local registry and closes the registry.log file
+func (o *ExecutorSchema) stopLocalRegistry(ctx context.Context) {
+	// Try to gracefully shutdown the local registry
+	ctx, cancel := context.WithTimeout(ctx, time.Second)


@r4f4 - +1 using context

lmzuccarelli · 2025-02-11T12:57:47Z

Verified locally using m2d d2m & m2m

lmzuccarelli · 2025-02-11T12:58:09Z

/lgtm
/label acknowledge-critical-fixes-only

lmzuccarelli · 2025-02-11T12:59:50Z

@r4f4 - I will wait for QE before adding the correct labels

aguidirh

Thanks @r4f4, a lot of good improvements.

I left only one comment, please let me know if you have questions about it.

aguidirh · 2025-02-11T13:34:05Z

v2/internal/pkg/cli/executor.go

-		interruptSig := NormalStorageInterruptErrorf("end of mirroring to disk. Stopping local storage to prepare the archive")
-		o.localStorageInterruptChannel <- interruptSig


The tar ball generated in the end of m2d is the data under ~/.oc-mirror/.cache. Since this data is used by the local registry running on top of oc-mirror cache, to avoid data corruption, it is better to stop the local registry before starting the preparation of the tarball.

Notice that the previous interrupt was not stopping the registry. But I can add the logic here. So this is only needed for the Mirror2Disk workflow, right?

Actually it seems we cannot stop the registry as the blob collector for the tarball still accesses the registry: https://github.com/openshift/oc-mirror/blob/main/v2/internal/pkg/archive/image-blob-gatherer.go#L24

2025/02/11 15:12:20 [INFO] : === Results === 2025/02/11 15:12:20 [INFO] : ✓ 193 / 193 release images mirrored successfully 2025/02/11 15:12:20 [INFO] : 📦 Preparing the tarball archive... 2025/02/11 15:12:24 [WARN] : Close registry.log failed: close /prjs/mirrors/oc-mirror-ocpbugs-49990/data/working-dir/logs/registry.log: file already closed 2025/02/11 15:12:24 [INFO] : 👋 Goodbye, thank you for using oc-mirror 2025/02/11 15:12:24 [ERROR] : unable to add image blobs to the archive : unable to find blobs corresponding to docker://localhost:55000/openshift/release:4.16.1-x86_64-ovirt-machine-controllers: pinging container registry localhost:55000: Get "http://localhost:55000/v2/": dial tcp [::1]:55000: connect: connection refused

openshift-ci bot requested review from aguidirh and lmzuccarelli February 5, 2025 23:46

lmzuccarelli reviewed Feb 6, 2025

View reviewed changes

r4f4 force-pushed the always-close-registry-log branch from 4217ffa to 25f0600 Compare February 6, 2025 08:51

openshift-ci bot changed the title ~~v2/cli: always stop local registry and close registry.log~~ OCPBUGS-50476: v2/cli: always stop local registry and close registry.log Feb 9, 2025

openshift-ci-robot added the jira/valid-reference Indicates that this PR references a valid Jira ticket of any type. label Feb 9, 2025

openshift-ci-robot added the jira/invalid-bug Indicates that a referenced Jira bug is invalid for the branch this PR is targeting. label Feb 9, 2025

openshift-ci-robot added jira/valid-bug Indicates that a referenced Jira bug is valid for the branch this PR is targeting. and removed jira/invalid-bug Indicates that a referenced Jira bug is invalid for the branch this PR is targeting. labels Feb 9, 2025

openshift-ci bot requested a review from zhouying7780 February 9, 2025 11:36

lmzuccarelli reviewed Feb 10, 2025

View reviewed changes

openshift-ci bot added the acknowledge-critical-fixes-only Indicates if the issuer of the label is OK with the policy. label Feb 11, 2025

openshift-ci bot assigned lmzuccarelli Feb 11, 2025

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Feb 11, 2025

aguidirh reviewed Feb 11, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

OCPBUGS-50476: v2/cli: always stop local registry and close registry.log #1068

OCPBUGS-50476: v2/cli: always stop local registry and close registry.log #1068

r4f4 commented Feb 5, 2025 •

edited

Loading

openshift-ci bot commented Feb 5, 2025

lmzuccarelli Feb 6, 2025

lmzuccarelli commented Feb 6, 2025

r4f4 commented Feb 6, 2025

r4f4 commented Feb 9, 2025

openshift-ci-robot commented Feb 9, 2025

Description

Type of change

How Has This Been Tested?

Expected Outcome

r4f4 commented Feb 9, 2025

openshift-ci-robot commented Feb 9, 2025

r4f4 commented Feb 9, 2025

openshift-ci bot commented Feb 9, 2025

lmzuccarelli Feb 10, 2025

lmzuccarelli commented Feb 11, 2025

lmzuccarelli commented Feb 11, 2025

lmzuccarelli commented Feb 11, 2025

aguidirh left a comment

aguidirh Feb 11, 2025

r4f4 Feb 11, 2025

r4f4 Feb 11, 2025

		interruptSig := NormalStorageInterruptErrorf("end of mirroring to disk. Stopping local storage to prepare the archive")
		o.localStorageInterruptChannel <- interruptSig

OCPBUGS-50476: v2/cli: always stop local registry and close registry.log #1068

Are you sure you want to change the base?

OCPBUGS-50476: v2/cli: always stop local registry and close registry.log #1068

Conversation

r4f4 commented Feb 5, 2025 • edited Loading

Description

Type of change

How Has This Been Tested?

Expected Outcome

openshift-ci bot commented Feb 5, 2025

lmzuccarelli Feb 6, 2025

Choose a reason for hiding this comment

lmzuccarelli commented Feb 6, 2025

r4f4 commented Feb 6, 2025

r4f4 commented Feb 9, 2025

openshift-ci-robot commented Feb 9, 2025

Description

Type of change

How Has This Been Tested?

Expected Outcome

r4f4 commented Feb 9, 2025

openshift-ci-robot commented Feb 9, 2025

r4f4 commented Feb 9, 2025

openshift-ci bot commented Feb 9, 2025

lmzuccarelli Feb 10, 2025

Choose a reason for hiding this comment

lmzuccarelli commented Feb 11, 2025

lmzuccarelli commented Feb 11, 2025

lmzuccarelli commented Feb 11, 2025

aguidirh left a comment

Choose a reason for hiding this comment

aguidirh Feb 11, 2025

Choose a reason for hiding this comment

r4f4 Feb 11, 2025

Choose a reason for hiding this comment

r4f4 Feb 11, 2025

Choose a reason for hiding this comment

r4f4 commented Feb 5, 2025 •

edited

Loading