Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Race in timeout failure report generation #815

Open
sywhang opened this issue Nov 18, 2021 · 3 comments · May be fixed by #816
Open

Race in timeout failure report generation #815

sywhang opened this issue Nov 18, 2021 · 3 comments · May be fixed by #816
Assignees

Comments

@sywhang
Copy link
Contributor

sywhang commented Nov 18, 2021

When there is a timeout, we try to generate a timeout report by printing what timed out. There is a race in this logic which sometimes results in CI failures like this:

    --- FAIL: TestAppStart/Timeout (0.01s)
9 app_test.go:905: 
10 Error Trace:	app_test.go:905
11 Error:      	"OnStart hook added by  failed: context deadline exceeded" does not contain "OnStart hook added by go.uber.org/fx_test.TestAppStart.func1.1 failed: context deadline exceeded"
12 Test:       	TestAppStart/Timeout
13 FAIL

We can actually repro this pretty easily by changing the timeout in TestAppStart/Timeout to 1 nanosecond:

context.WithTimeout(context.Background(), time.Nanosecond)
fx ➤ make test                                                                                                                                                                                git:master*
--- FAIL: TestAppStart (0.00s)
    --- FAIL: TestAppStart/Timeout (0.00s)
        app_test.go:905:
                Error Trace:    app_test.go:905
                Error:          "OnStart hook added by  failed: context deadline exceeded" does not contain "OnStart hook added by go.uber.org/fx_test.TestAppStart.func1.1 failed: context deadline exceeded"
                Test:           TestAppStart/Timeout
@sywhang sywhang self-assigned this Nov 18, 2021
@sywhang
Copy link
Contributor Author

sywhang commented Nov 20, 2021

Looks like #813 should also have addressed this issue. Closing as done.

@sywhang sywhang closed this as completed Nov 20, 2021
@sywhang
Copy link
Contributor Author

sywhang commented Nov 20, 2021

Actually, very short-lived processes can still run into this issue... Reopening.

@sywhang sywhang reopened this Nov 20, 2021
sywhang added a commit to sywhang/fx that referenced this issue Nov 20, 2021
When fx is run with a very short timeout, it's possible for the
timeout error message to be in a bad format "OnStart hook added by  failed"
where the name of the OnStart hook's caller hasn't been recorded
before the context times out.

This fixes the error message generation to not rely on the OnStart hook's
caller always being known to fix this race.

Fixes uber-go#815
@sywhang sywhang linked a pull request Nov 20, 2021 that will close this issue
sywhang added a commit to sywhang/fx that referenced this issue Nov 20, 2021
When fx is run with a very short timeout, it's possible for the
timeout error message to be in a bad format "OnStart hook added by  failed"
where the name of the OnStart hook's caller hasn't been recorded
before the context times out.

This fixes the error message generation to not rely on the OnStart hook's
caller always being known to fix this race.

Fixes uber-go#815
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging a pull request may close this issue.

2 participants
@sywhang and others