CBG-3700 fix race conditions #6633

torcolvin · 2024-01-08T16:26:40Z

Addresses a race in go test -tags cb_sg_enterprise ./rest/replicatortest -race -run TestGroupIDReplications

each ServerContext will reset the global logger. Provide a way to avoid the logging setup, assuming that the test logging framework will already be configured. The logger can get reset while a different server (database) is logging, such as writing checkpoint documents.
dbReplicatorStats map can be accessed simultaneously by SGReplicateMgr and when it is explicitly called in the test.

I don't really care for the way I avoid re-initialization of the global logger, but I don't have a better alternative in mind.

Pre-review checklist

Removed debug logging (fmt.Print, log.Print, ...)
Logging sensitive data? Make sure it's tagged (e.g. base.UD(docID), base.MD(dbName))
Updated relevant information in the API specifications (such as endpoint descriptions, schemas, ...) in docs/api

Integration Tests

GSI=true,xattrs=true https://jenkins.sgwdev.com/job/SyncGateway-Integration/2450/

- each ServerContext will reset the global logger. Provide a way to avoid the logging setup, assuming that the test logging framework will already be configured. The logger can get reset while a different server (database) is logging, such as writing checkpoint documents. - dbReplicatorStats map can be accessed simultaneously by SGReplicateMgr and when it is explicitly called in the test.

base/stats.go

adamcfraser · 2024-01-08T18:52:38Z

rest/config_startup.go

@@ -85,6 +85,8 @@ type StartupConfig struct {
 	CouchbaseKeepaliveInterval *int   `json:"couchbase_keepalive_interval,omitempty" help:"TCP keep-alive interval between SG and Couchbase server"`

 	DeprecatedConfig *DeprecatedConfig `json:"-,omitempty" help:"Deprecated options that can be set from a legacy config upgrade, but cannot be set from a 3.0 config."`
+
+	avoidLoggingSetup bool `json:"-"` // Used to avoid logging setup so as to not modify globals. This only used for testing multiple ServerContexts simultaneously. This will use the same logging configuration as is already set up.


Do you think we could build this into initLogging, so that callers don't need to worry about setting this flag? (i.e. have InitLogging run within a mutex and set a global flag when complete, and check that flag when run)

There's a single test TestConfigsIncludeDefaults that requires initialization of a logger, to test whether it will pass the DCP base key to the database level. I'm not convinced this part of this test needs the workaround defer RunBootstrapLoggerInitialization(t)().

I don't know if I like this solution better because it relies on a global but I think it makes the part of the code to be modified very small, which I like.

From the previous commit, I had the impression that we should only ever be calling SetupAndValidateLogging once per process. (and that unit tests with multiple server contexts should reuse the same logging config). Is that accurate? If yes, I think we should be encapsulate the 'run once' logic inside SetupAndValidateLogging.

I looked at TestConfigsIncludeDefaults and I think it can just use SetUpTestLogging to initialize the DCP log key - I don't think it needs a custom call to SetupAndValidateLogging.

I needed to add config.Logging.Console.Enabled = base.BoolPtr(true) to this test, which is normally enabled as a side effect of InitLogging but not normally needed in a JSON for server config. I think this is fine for this test, which keeps the guts of the inheritance.

…only need for a single test

Co-authored-by: Adam Fraser <[email protected]>

This causes a race condition in the instance that two databases with the same config group are created simultaneously. An example of how this can happen is: - config polling to pick up a db config A - GET /dbA/ The second will independently attempt to load the configuration while the first is running. In theory, this could happen for any different database in step 2, since all databases will be in the same group id.

adamcfraser · 2024-01-09T00:00:21Z

rest/config.go

-		log.Printf("[ERR] Error setting up logging: %v", err)
-		return nil, fmt.Errorf("error setting up logging: %v", err)
+	// logger will be initialized only when running tests
+	if !loggerInitialized {


This doesn't feel like quite the right place to be using this variable - wouldn't we'd want to encapsulate it in the logging handling (inside SetupAndValidateLogging)?

We'd also still need some sort of synchronization to avoid races.

adamcfraser · 2024-01-09T00:14:42Z

rest/config_startup.go

@@ -85,6 +85,8 @@ type StartupConfig struct {
 	CouchbaseKeepaliveInterval *int   `json:"couchbase_keepalive_interval,omitempty" help:"TCP keep-alive interval between SG and Couchbase server"`

 	DeprecatedConfig *DeprecatedConfig `json:"-,omitempty" help:"Deprecated options that can be set from a legacy config upgrade, but cannot be set from a 3.0 config."`
+
+	avoidLoggingSetup bool `json:"-"` // Used to avoid logging setup so as to not modify globals. This only used for testing multiple ServerContexts simultaneously. This will use the same logging configuration as is already set up.


From the previous commit, I had the impression that we should only ever be calling SetupAndValidateLogging once per process. (and that unit tests with multiple server contexts should reuse the same logging config). Is that accurate? If yes, I think we should be encapsulate the 'run once' logic inside SetupAndValidateLogging.

I looked at TestConfigsIncludeDefaults and I think it can just use SetUpTestLogging to initialize the DCP log key - I don't think it needs a custom call to SetupAndValidateLogging.

bbrks · 2024-01-11T13:47:07Z

rest/config.go

+	// If SetupServerContext is called while any other go routines that might use logging are running, it will
+	// cause a data race, therefore only initialize logging and other globals on the first call. From a main
+	// program, there is only one ServerContext.
+	if serverContextGlobalsInitialized.CompareAndSwap(false, true) {


I'm not sure how this is intended to work for a suite of tests that only invoke SetupServerContext once per test.

Is it expected that only the first test gets to set global config, and all others can't?

I'd have expected this flag to be reset between tests maybe (t.Cleanup?), if the intention is to only allow this to be run once per test to avoid races

bbrks · 2024-01-11T13:47:56Z

rest/config.go

+	// If SetupServerContext is called while any other go routines that might use logging are running, it will
+	// cause a data race, therefore only initialize logging and other globals on the first call. From a main


Doesn't protect against tests that have a mix of RestTester and full Bootstrap/ServerContext (e.g. TestGroupIDReplications)

- each ServerContext will reset the global logger. Only reset the global logging once per execution of the program, to simulate what happens in mane. - dbReplicatorStats map can be accessed simultaneously by SGReplicateMgr and when it is explicitly called in the test. - Mutex RegisterImportPindexImpl which was unsynchronized when multiple calls to NewDatabaseContext happen simultaneously.

torcolvin added 2 commits January 8, 2024 11:22

Optionally skip logging config

502839e

torcolvin requested a review from adamcfraser January 8, 2024 17:36

torcolvin assigned adamcfraser Jan 8, 2024

adamcfraser requested changes Jan 8, 2024

View reviewed changes

adamcfraser assigned torcolvin and unassigned adamcfraser Jan 8, 2024

Create a rest package level variable to initialize logging, which we …

5f3dcd3

…only need for a single test

torcolvin assigned adamcfraser and unassigned torcolvin Jan 8, 2024

adamcfraser assigned torcolvin and unassigned adamcfraser Jan 9, 2024

torcolvin and others added 3 commits January 8, 2024 20:25

Update base/stats.go mutex name

ea48f18

Co-authored-by: Adam Fraser <[email protected]>

Fix variable spelling

f6b08d6

torcolvin assigned adamcfraser and unassigned torcolvin Jan 9, 2024

adamcfraser reviewed Jan 9, 2024

View reviewed changes

adamcfraser assigned torcolvin and unassigned adamcfraser Jan 9, 2024

Put the loggingInitialized atomic in base package

846ff7f

torcolvin assigned adamcfraser and unassigned torcolvin Jan 9, 2024

torcolvin added 4 commits January 9, 2024 19:54

Remove unnecessary setting variable

746fdf5

Look for test in the single place tests are likely to collide

5061eb7

Use an atomic for one time logging initialization

83f1e87

Change variable to include all globals

0b0675e

torcolvin enabled auto-merge (squash) January 10, 2024 20:13

adamcfraser approved these changes Jan 10, 2024

View reviewed changes

torcolvin merged commit 2e37dac into master Jan 10, 2024
29 of 30 checks passed

torcolvin deleted the CBG-3700 branch January 10, 2024 21:40

bbrks reviewed Jan 11, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CBG-3700 fix race conditions #6633

CBG-3700 fix race conditions #6633

torcolvin commented Jan 8, 2024 •

edited

Loading

adamcfraser Jan 8, 2024

torcolvin Jan 8, 2024

adamcfraser Jan 9, 2024

torcolvin Jan 9, 2024

adamcfraser Jan 9, 2024

adamcfraser Jan 9, 2024

bbrks Jan 11, 2024

bbrks Jan 11, 2024

		// If SetupServerContext is called while any other go routines that might use logging are running, it will
		// cause a data race, therefore only initialize logging and other globals on the first call. From a main

CBG-3700 fix race conditions #6633

CBG-3700 fix race conditions #6633

Conversation

torcolvin commented Jan 8, 2024 • edited Loading

Pre-review checklist

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

torcolvin commented Jan 8, 2024 •

edited

Loading