Resolved race condition in collector when calling Shutdown

[cpheps]

Description:

• Refactored collector shutdown pattern to fix race condition detailed in Collector Shutdown will not be honored if called to early #4843

Link to tracking Issue: Fixes #4843

Testing: Verified existing tests still work. Added unit test to verify calling Shutdown while collector is not running will cause an immediate shutdown when Run is called.

[codecov]

Codecov Report

Merging #4878 (b8cbfa2) into main (5f2d874) will increase coverage by 0.00%.
The diff coverage is 100.00%.

@@           Coverage Diff           @@
##             main    #4878   +/-   ##
=======================================
  Coverage   91.02%   91.02%           
=======================================
  Files         178      178           
  Lines       10597    10600    +3     
=======================================
+ Hits         9646     9649    +3     
  Misses        734      734           
  Partials      217      217           

Impacted Files	Coverage Δ
service/collector.go	75.65% <100.00%> (+0.49%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 5f2d874...b8cbfa2. Read the comment docs.

[codeboten]

nit: The comment here should start with the func name, alternatively the comment could be moved inside func

[bogdandrutu]

I think this PR changes more than needed to fix the problem.

The adding of a new state is completely independent and should be a separate PR.

[cpheps]

I think this PR changes more than needed to fix the problem.
The adding of a new state is completely independent and should be a separate PR.

@bogdandrutu So I added a new state because with out it the Collector is in a Starting state but hasn't actually started. If I call Shutdown before I call Run what should the collector do? If we don't include a new state calling Shutdown before calling Run will prevent the collector from actually starting. It puts it in a weird state where you have a collector that says it's in the Starting state but has no hope of ever running.

You're right the new state isn't technically needed to solve this problem but without a way to tell that the collector has been created and not run ,Shutdown can put the collector in a weird state.

I'm curious if you have another solution to this were we can avoid a new state.

[buptubuntu]

I think this PR changes more than needed to fix the problem.

The adding of a new state is completely independent and should be a separate PR.

Maybe we change the title of the PR to Add state in collector lifecycle? And the Created can resolve condition race.

@cpheps what do you think?

[cpheps]

@buptubuntu I think that's fair. I think without the new state we trade a race condition a less than ideal behavior pattern for the collector.

[cpheps]

@bogdandrutu Curious if I can get your thoughts on my reply and @buptubuntu's suggestion?

[bogdandrutu]

Why at the end? I don't think we guarantee the numbers.

[bogdandrutu]

If I call Shutdown before I call Run what should the collector do?

@cpheps this is probably the most important question.

I think we should do what the "language pattern" is, so probably we should do exactly what http server does for shutdown https://pkg.go.dev/net/http#Server.Shutdown and document the behavior better.

[cpheps]

I think we should do what the "language pattern" is, so probably we should do exactly what http server does for shutdown https://pkg.go.dev/net/http#Server.Shutdown and document the behavior better.

@bogdandrutu I think that's fair. Looks like if you call shutdown on a server it will not allow it to start or will cause any listen function to immediately close. So for the collector it should do the same. I think this eliminates the need for a new state. I'll remove the created state and rename the PR back to the way it was.

Do you have any concerns on how fast the collector shutdown if Shutdown is called before Run? Seems like it will go through the entire startup process change it's state to Running then shut down. All this should be more or less instant to a user and honestly calling Shutdown pre run is not a normal use case. I think it should be fine but wanted to pose the question.

[cpheps]

@bogdandrutu Removed the extra state. Do you mind taking a re-review?

[cpheps]

Looks like CI failures are unrelated to changes.

[cpheps]

Probably in a separate PR, but we should block for shutdown to return when complete correct?

Do you mean block in the shutdown function? I suppose we can, in http.server it waits for all the listeners to close down. If it's called before a Listenandserve type function there are no listeners to wait for so it exits.

For us I think we need to do some refactoring to figure out what shutdown is waiting on and ensure it doesn't block forever if called before Run. I don't think it can be the collector state as that currently won't change if Run is not executed.

Also RUN should probably not start everything if shutdown was called.

I agree on this but I felt like it was out of the scope of the PR as we probably need to restructure the startup logic.

I'll write up issues for these. I think the former needs more discussion.

[bogdandrutu]

@cpheps I think your test catch you :)

2022-03-01T17:53:33.131Z	warn	zapgrpc/zapgrpc.go:191	[core] grpc: addrConn.createTransport failed to connect to {locahost:4317 locahost:4317 <nil> <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp: operation was canceled"	{"grpc_log": true}
2022-03-01T17:53:33.133Z	info	service/collector.go:266	Shutdown complete.
    testing.go:1152: race detected during execution of test
--- FAIL: TestCollector_ShutdownBeforeRun (0.24s)
=== RUN   TestCollector_ReportError

[cpheps]

I'll double check. They were running locally even the service one that keeps failing. It might be flaky I'll check.

[cpheps]

Oh I see it's the race detector I'll take a look.

[cpheps]

@bogdandrutu This is actually interesting as you brought this up on my last PR. The data race is due to access to the logger pointer is not atomic. I wrote up and issue to track the atomic log pointer at #4939.

Would you be opposed to removing the log statement in the recover for shutdown? It's not a user friendly log and doesn't seem very helpful from a user's standpoint since it's referring to an unexported channel.

We could add it back once the log pointer is atomic but I don't think the message is useful enough to block merging this PR.

[bogdandrutu]

+1 on removing the log

[Chinwendu20]

Hi @cpheps please I was looking through this and I was wondering how you came up with time in the assert.eventually() function

[cpheps]

@Chinwendu20 the time is a bit arbitrary. Shutdown should be almost instant. I picked 2 seconds because that should be more than enough time for Shutdown to work. It's also short enough where it shutdown fails it does not slow the entire test suit down significantly.

[Chinwendu20]

Thank you so much @cpheps. I see this PR is related to the shutdown not being honored if called right after run. I would like to please know why you called Shutdown() before run in this test case. I see the comment on the code right after, that call but I still do not get it.

Thanks a lot

[cpheps]

@Chinwendu20 This specific test case is to ensure if you call Shutdown before Run it means run will exit. Looking at the test I think the col.Shutdown() on line 211 is not suppose to be there. It's not contaminating the test I don't think but might be muddling the intent.

The order of operations should be this:

1. Create collector
2. Shutdown collector
3. Run collector

We expect that collector should exit run within a reasonable amount of time (hence the 2 second timer). Currently though the collector has to run through its entire startup then detect the shutdown and exit. The issue you're working on should make it so as soon as Run is called it should check to see if Shutdown has been called and if so just exit rather than running any logic.