CBG-5472: Make the stats logger independent of the database lock

[bbrks]

CBG-5472

Avoid blocking stats logger from database updates and initialisations. Access lock-free version of databases on ServerContext to build stats and minimise the locking required inside DbStats.

Pre-review checklist

• Self-review @bbrks

Dependencies (if applicable)

• CBG-3658: Prevent non-finite CPU stat from corrupting stats serialization #8430

Integration Tests

• https://jenkins.sgwdev.com/job/SyncGatewayIntegration/959/
  • (fixed failing unit test)

[Copilot]

Pull request overview

Copilot reviewed 7 out of 7 changed files in this pull request and generated no new comments.

[torcolvin]

Pretty much just readability comments and hoping to screw this up in the future.

[torcolvin]

I think conceptually Stopping makes more sense here?

[torcolvin]

Rather than this comment, I'd be inclined to make this a type with Insert / Delete / Clear for modification and a Snapshot function?

[torcolvin]

I'd feel better if this was in a function with a defer in the rare case that there is something that panics when unloading the database - if there is something that goes wrong when unloading a database, locking the stats would make it impossible to debug

[torcolvin]

This doesn't seem right here?

[torcolvin]

use WaitWithTimeout for sync group waiting.

[torcolvin]

Should you do wait in a defer? and use WaitWithTimeout for sync group waiting.

[torcolvin]

I hit a separate race condition and I've developed a test for it in stats_test.go - this PR fixes test but not the other.

// TestDbReplicatorStatsUnsynchronisedAccess covers concurrent access to DbStats.DbReplicatorStats:
// creating a replication's stats while something else walks the stats tree.  Run with -race.
//
// The expvar case is the one reachable in a running Sync Gateway: any metrics or expvar read that
// lands while a replication is initialising.  The teardown case needs two live DatabaseContexts
// sharing a database name, since DbStats is keyed by name.
func TestDbReplicatorStatsUnsynchronisedAccess(t *testing.T) {
	const iterations = 200

	t.Run("expvar read while creating", func(t *testing.T) {
		const dbName = "statsRaceExpvarDb"
		dbStats, err := SyncGatewayStats.NewDBStats(dbName, false, false, false, false, []string{}, []string{})
		require.NoError(t, err)
		defer SyncGatewayStats.ClearDBStats(dbName)

		var wg sync.WaitGroup
		wg.Go(func() {
			for i := range iterations {
				_, err := dbStats.DBReplicatorStats(fmt.Sprintf("replication%d", i))
				assert.NoError(t, err)
			}
		})
		// SgwStats.String marshals the whole tree, including DbReplicatorStats.
		wg.Go(func() {
			for range iterations {
				_ = SyncGatewayStats.String()
			}
		})
		WaitWithTimeout(t, &wg, time.Minute)
	})

	t.Run("stats teardown while creating", func(t *testing.T) {
		const dbName = "statsRaceTeardownDb"
		// One Clear per iteration: it deletes the map entry, so repeated calls on the same entry return
		// early and never reach the unregister loop.  Replication IDs are unique per iteration so stats
		// created after a Clear has walked the map cannot collide with the next iteration's registration.
		for outer := range iterations {
			dbStats, err := SyncGatewayStats.NewDBStats(dbName, false, false, false, false, []string{}, []string{})
			require.NoError(t, err)

			var wg sync.WaitGroup
			wg.Go(func() {
				for i := range 20 {
					_, err := dbStats.DBReplicatorStats(fmt.Sprintf("replication%d-%d", outer, i))
					assert.NoError(t, err)
				}
			})
			// ClearDBStats iterates DbReplicatorStats to unregister them.
			wg.Go(func() {
				SyncGatewayStats.ClearDBStats(dbName)
			})
			WaitWithTimeout(t, &wg, time.Minute)

			SyncGatewayStats.ClearDBStats(dbName)
		}
	})
}

Before I realised this PR was touching the same code, this is my proposed fix https://github.com/couchbase/sync_gateway/pull/new/dbstats-race - see the message for a longer description.

I hit this bug here https://jenkins.sgwdev.com/job/Pipeline/job/PR-8608/1/testReport/junit/(root)/EE-rest_replicatortest/TestReplicationHeartbeatRemovalPushWithConfigReload_versionVector/ on #8608.

[torcolvin]

I hit a separate race condition and I've developed a test for it in stats_test.go - this PR fixes test but not the other.

// TestDbReplicatorStatsUnsynchronisedAccess covers concurrent access to DbStats.DbReplicatorStats:
// creating a replication's stats while something else walks the stats tree.  Run with -race.
//
// The expvar case is the one reachable in a running Sync Gateway: any metrics or expvar read that
// lands while a replication is initialising.  The teardown case needs two live DatabaseContexts
// sharing a database name, since DbStats is keyed by name.
func TestDbReplicatorStatsUnsynchronisedAccess(t *testing.T) {
	const iterations = 200

	t.Run("expvar read while creating", func(t *testing.T) {
		const dbName = "statsRaceExpvarDb"
		dbStats, err := SyncGatewayStats.NewDBStats(dbName, false, false, false, false, []string{}, []string{})
		require.NoError(t, err)
		defer SyncGatewayStats.ClearDBStats(dbName)

		var wg sync.WaitGroup
		wg.Go(func() {
			for i := range iterations {
				_, err := dbStats.DBReplicatorStats(fmt.Sprintf("replication%d", i))
				assert.NoError(t, err)
			}
		})
		// SgwStats.String marshals the whole tree, including DbReplicatorStats.
		wg.Go(func() {
			for range iterations {
				_ = SyncGatewayStats.String()
			}
		})
		WaitWithTimeout(t, &wg, time.Minute)
	})

	t.Run("stats teardown while creating", func(t *testing.T) {
		const dbName = "statsRaceTeardownDb"
		// One Clear per iteration: it deletes the map entry, so repeated calls on the same entry return
		// early and never reach the unregister loop.  Replication IDs are unique per iteration so stats
		// created after a Clear has walked the map cannot collide with the next iteration's registration.
		for outer := range iterations {
			dbStats, err := SyncGatewayStats.NewDBStats(dbName, false, false, false, false, []string{}, []string{})
			require.NoError(t, err)

			var wg sync.WaitGroup
			wg.Go(func() {
				for i := range 20 {
					_, err := dbStats.DBReplicatorStats(fmt.Sprintf("replication%d-%d", outer, i))
					assert.NoError(t, err)
				}
			})
			// ClearDBStats iterates DbReplicatorStats to unregister them.
			wg.Go(func() {
				SyncGatewayStats.ClearDBStats(dbName)
			})
			WaitWithTimeout(t, &wg, time.Minute)

			SyncGatewayStats.ClearDBStats(dbName)
		}
	})
}

Before I realised this PR was touching the same code, this is my proposed fix couchbase/sync_gateway/pull/new/dbstats-race - see the message for a longer description.

I hit this bug here jenkins.sgwdev.com/job/Pipeline/job/PR-8608/1/testReport/junit/(root)/EE-rest_replicatortest/TestReplicationHeartbeatRemovalPushWithConfigReload_versionVector on #8608.

Actually, I know what the problem is here: to test ISGR rebalancing, I create two databases on the same "node" in the same config group. In this case, they have to share the same database name, and this behavior is expected.

However, this would never occur in the real world because a sync gateway production node can't have two databases with the same name on the same node.

This means this problem probably still could be fixed with locking in this code, however it is test only.