diff --git a/pkg/logservice/client.go b/pkg/logservice/client.go index 28ea88bfbb41a..62ae0e49a7ee8 100644 --- a/pkg/logservice/client.go +++ b/pkg/logservice/client.go @@ -37,6 +37,13 @@ const ( defaultWriteSocketSize = 64 * 1024 ) +var ( + logServiceConnectAttemptTimeout = 5 * time.Second + logServiceConnectFallbackDelay = 300 * time.Millisecond +) + +var connectToLogServiceAddressFn = connectToLogServiceAddress + // IsTempError returns a boolean value indicating whether the specified error // is a temp error that worth to be retried, e.g. timeouts, temp network // issues. Non-temp error caused by program logics rather than some external @@ -468,7 +475,12 @@ func connectToLogServiceByReverseProxy( if !ok { return nil, moerr.NewLogServiceNotReady(ctx) } - addresses := make([]string, 0) + addresses := shardInfoReplicaAddresses(si) + return connectToLogServiceAddresses(ctx, sid, addresses, cfg) +} + +func shardInfoReplicaAddresses(si ShardInfo) []string { + addresses := make([]string, 0, len(si.Replicas)) leaderAddress, ok := si.Replicas[si.ReplicaID] if ok { addresses = append(addresses, leaderAddress) @@ -478,7 +490,7 @@ func connectToLogServiceByReverseProxy( addresses = append(addresses, address) } } - return connectToLogService(ctx, sid, addresses, cfg) + return addresses } func connectToLogService( @@ -490,7 +502,19 @@ func connectToLogService( if len(targets) == 0 { return nil, nil } + addresses := append([]string{}, targets...) + rand.Shuffle(len(addresses), func(i, j int) { + addresses[i], addresses[j] = addresses[j], addresses[i] + }) + return connectToLogServiceAddresses(ctx, sid, addresses, cfg) +} +func connectToLogServiceAddress( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, +) (*client, error) { pool := &sync.Pool{} pool.New = func() interface{} { return &RPCRequest{pool: pool} @@ -504,51 +528,194 @@ func connectToLogService( pool: pool, respPool: respPool, } - var e error - addresses := append([]string{}, targets...) - rand.Shuffle(len(cfg.ServiceAddresses), func(i, j int) { - addresses[i], addresses[j] = addresses[j], addresses[i] - }) - for _, addr := range addresses { - cc, err := getRPCClient( - ctx, - sid, - addr, - c.respPool, - c.cfg.MaxMessageSize, - cfg.EnableCompress, - 0, - cfg.Tag, - ) - if err != nil { - e = err - continue + cc, err := getRPCClient( + ctx, + sid, + addr, + c.respPool, + c.cfg.MaxMessageSize, + cfg.EnableCompress, + 0, + cfg.Tag, + ) + if err != nil { + return nil, err + } + c.addr = addr + c.client = cc + if cfg.ReadOnly { + if err := c.connectReadOnly(ctx); err != nil { + if closeErr := c.close(); closeErr != nil { + logutil.Error("failed to close the client", zap.Error(closeErr)) + } + return nil, err + } + return c, nil + } + // TODO: add a test to check whether it works when there is no truncated + // LSN known to the logservice. + if err := c.connectReadWrite(ctx); err != nil { + if closeErr := c.close(); closeErr != nil { + logutil.Error("failed to close the client", zap.Error(closeErr)) } - c.addr = addr - c.client = cc - if cfg.ReadOnly { - if err := c.connectReadOnly(ctx); err == nil { - return c, nil - } else { - if err := c.close(); err != nil { - logutil.Error("failed to close the client", zap.Error(err)) + return nil, err + } + return c, nil +} + +type connectResult struct { + client *client + err error +} + +func connectToLogServiceAddresses( + ctx context.Context, + sid string, + addresses []string, + cfg ClientConfig, +) (*client, error) { + ctx, cancel := context.WithCancel(ctx) + defer cancel() + + if err := ctx.Err(); err != nil { + return nil, err + } + + results := make(chan connectResult, len(addresses)) + var wg sync.WaitGroup + launch := func(addr string) { + wg.Add(1) + go func() { + defer wg.Done() + attemptCtx, attemptCancel := connectAttemptContext(ctx) + defer attemptCancel() + + c, err := connectToLogServiceAddressFn(attemptCtx, sid, addr, cfg) + if err == nil { + if err := ctx.Err(); err != nil { + if closeErr := c.close(); closeErr != nil { + logutil.Error("failed to close the client", zap.Error(closeErr)) + } + return + } + select { + case results <- connectResult{client: c}: + case <-ctx.Done(): + if closeErr := c.close(); closeErr != nil { + logutil.Error("failed to close the client", zap.Error(closeErr)) + } } - e = err + return + } + select { + case results <- connectResult{err: moerr.AttachCause(attemptCtx, err)}: + case <-ctx.Done(): + } + }() + } + + var lastErr error + launched, active := 0, 0 + for active > 0 || launched < len(addresses) { + if active == 0 { + if err := ctx.Err(); err != nil { + return nil, err + } + launch(addresses[launched]) + launched++ + active++ + continue + } + + var fallback <-chan time.Time + var timer *time.Timer + if launched < len(addresses) { + timer = time.NewTimer(logServiceConnectFallbackDelay) + fallback = timer.C + } + + select { + case r := <-results: + stopConnectFallbackTimer(timer) + active-- + if r.client != nil { + cleanupConnectAttempts(cancel, &wg, results) + return r.client, nil } - } else { - // TODO: add a test to check whether it works when there is no truncated - // LSN known to the logservice. - if err := c.connectReadWrite(ctx); err == nil { - return c, nil - } else { - if err := c.close(); err != nil { - logutil.Error("failed to close the client", zap.Error(err)) + lastErr = r.err + case <-fallback: + if err := ctx.Err(); err != nil { + cleanupConnectAttempts(cancel, &wg, results) + return nil, err + } + launch(addresses[launched]) + launched++ + active++ + case <-ctx.Done(): + stopConnectFallbackTimer(timer) + cleanupConnectAttempts(cancel, &wg, results) + return nil, connectContextError(ctx.Err(), lastErr) + } + } + wg.Wait() + return nil, lastErr +} + +func connectAttemptContext(ctx context.Context) (context.Context, context.CancelFunc) { + if _, ok := ctx.Deadline(); ok { + return context.WithCancel(ctx) + } + return context.WithTimeoutCause( + ctx, + logServiceConnectAttemptTimeout, + moerr.CauseNewLogServiceClient, + ) +} + +func cleanupConnectAttempts( + cancel context.CancelFunc, + wg *sync.WaitGroup, + results <-chan connectResult, +) { + cancel() + go func() { + wg.Wait() + closeUnusedConnectResultClients(results) + }() +} + +func connectContextError(ctxErr error, lastErr error) error { + if ctxErr == nil || lastErr == nil { + return ctxErr + } + return errors.Wrapf(ctxErr, "last logservice connect error: %v", lastErr) +} + +func closeUnusedConnectResultClients(results <-chan connectResult) { + for { + select { + case r := <-results: + if r.client != nil { + if closeErr := r.client.close(); closeErr != nil { + logutil.Error("failed to close the client", zap.Error(closeErr)) } - e = err } + default: + return + } + } +} + +func stopConnectFallbackTimer(timer *time.Timer) { + if timer == nil { + return + } + if !timer.Stop() { + select { + case <-timer.C: + default: } } - return nil, e } func (c *client) close() error { diff --git a/pkg/logservice/client_test.go b/pkg/logservice/client_test.go index 1eea2f9663a1c..e5601a1b7d349 100644 --- a/pkg/logservice/client_test.go +++ b/pkg/logservice/client_test.go @@ -19,6 +19,8 @@ import ( "crypto/rand" "fmt" "math" + "net" + "sync" "testing" "time" @@ -147,6 +149,545 @@ func TestClientCanBeConnectedByReverseProxy(t *testing.T) { }() } +func TestClientCreationFallsBackFromUnreachableReplicaAddress(t *testing.T) { + defer leaktest.AfterTest(t)() + var cfg Config + genCfg := func() Config { + cfg = getServiceTestConfig() + return cfg + } + defer vfs.ReportLeakedFD(cfg.FS, t) + service, err := NewServiceWithRetry( + genCfg, + newFS(), + nil, + WithBackendFilter(func(msg morpc.Message, backendAddr string) bool { + return true + }), + ) + require.NoError(t, err) + defer func() { + assert.NoError(t, service.Close()) + }() + + init := make(map[uint64]string) + init[2] = service.ID() + require.NoError(t, service.store.startReplica(1, 2, init, false)) + + hangingAddress, cleanup := startHangingTCPServer(t) + defer cleanup() + + scfg := ClientConfig{ + LogShardID: 1, + TNReplicaID: 2, + MaxMessageSize: defaultMaxMessageSize, + } + + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectFallbackDelay = 50 * time.Millisecond + defer func() { logServiceConnectFallbackDelay = origFallbackDelay }() + + timeout := 5 * time.Second + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + start := time.Now() + c, err := connectToLogServiceAddresses(ctx, "", []string{ + hangingAddress, + cfg.LogServiceServiceAddr(), + }, scfg) + elapsed := time.Since(start) + + require.NoError(t, err) + require.NotNil(t, c) + defer func() { + assert.NoError(t, c.close()) + }() + assert.Less(t, elapsed, time.Second) +} + +func TestShardInfoReplicaAddressesKeepsLeaderFirst(t *testing.T) { + addresses := shardInfoReplicaAddresses(ShardInfo{ + ReplicaID: 2, + Replicas: map[uint64]string{ + 1: "replica-1", + 2: "leader", + 3: "replica-3", + }, + }) + require.Len(t, addresses, 3) + assert.Equal(t, "leader", addresses[0]) + assert.ElementsMatch(t, []string{"leader", "replica-1", "replica-3"}, addresses) +} + +func TestConnectToLogServiceWithNoTargets(t *testing.T) { + c, err := connectToLogService(context.Background(), "", nil, ClientConfig{}) + require.NoError(t, err) + require.Nil(t, c) +} + +func TestConnectToLogServiceAddressesReturnsLastError(t *testing.T) { + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectFallbackDelay = time.Millisecond + defer func() { + logServiceConnectFallbackDelay = origFallbackDelay + }() + + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() + c, err := connectToLogServiceAddresses(ctx, "", []string{ + "127.0.0.1:1", + "127.0.0.1:2", + }, ClientConfig{MaxMessageSize: defaultMaxMessageSize}) + require.Error(t, err) + require.Nil(t, c) +} + +func TestConnectToLogServiceAddressesReturnsContextError(t *testing.T) { + hangingAddress, cleanup := startHangingTCPServer(t) + defer cleanup() + + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectFallbackDelay = time.Second + defer func() { + logServiceConnectFallbackDelay = origFallbackDelay + }() + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + c, err := connectToLogServiceAddresses( + ctx, + "", + []string{hangingAddress}, + ClientConfig{MaxMessageSize: defaultMaxMessageSize}, + ) + require.Error(t, err) + require.ErrorIs(t, err, context.DeadlineExceeded) + require.Nil(t, c) +} + +func TestConnectToLogServiceAddressesReturnsContextErrorAfterPreviousFailure(t *testing.T) { + origConnect := connectToLogServiceAddressFn + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectFallbackDelay = time.Millisecond + defer func() { + connectToLogServiceAddressFn = origConnect + logServiceConnectFallbackDelay = origFallbackDelay + }() + + firstErr := errors.New("first failed") + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + if addr == "first" { + return nil, firstErr + } + <-ctx.Done() + time.Sleep(10 * time.Millisecond) + return nil, ctx.Err() + } + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + c, err := connectToLogServiceAddresses( + ctx, + "", + []string{"first", "second"}, + ClientConfig{}, + ) + require.Error(t, err) + require.ErrorIs(t, err, context.DeadlineExceeded) + require.ErrorContains(t, err, firstErr.Error()) + require.Nil(t, c) +} + +func TestConnectToLogServiceAddressesUsesCallerContextForAttempts(t *testing.T) { + origConnect := connectToLogServiceAddressFn + origAttemptTimeout := logServiceConnectAttemptTimeout + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectAttemptTimeout = time.Second + logServiceConnectFallbackDelay = time.Millisecond + defer func() { + connectToLogServiceAddressFn = origConnect + logServiceConnectAttemptTimeout = origAttemptTimeout + logServiceConnectFallbackDelay = origFallbackDelay + }() + + deadlines := make(chan time.Time, 2) + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + deadline, ok := ctx.Deadline() + require.True(t, ok) + deadlines <- deadline + <-ctx.Done() + return nil, ctx.Err() + } + + ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + defer cancel() + expectedDeadline, ok := ctx.Deadline() + require.True(t, ok) + c, err := connectToLogServiceAddresses( + ctx, + "", + []string{"first", "second"}, + ClientConfig{}, + ) + require.Error(t, err) + require.ErrorIs(t, err, context.DeadlineExceeded) + require.Nil(t, c) + for i := 0; i < 2; i++ { + require.WithinDuration(t, expectedDeadline, <-deadlines, time.Millisecond) + } +} + +func TestConnectToLogServiceAddressesAddsDeadlineForBackgroundContext(t *testing.T) { + origConnect := connectToLogServiceAddressFn + origAttemptTimeout := logServiceConnectAttemptTimeout + logServiceConnectAttemptTimeout = 20 * time.Millisecond + defer func() { + connectToLogServiceAddressFn = origConnect + logServiceConnectAttemptTimeout = origAttemptTimeout + }() + + deadlineSeen := make(chan struct{}, 1) + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + _, ok := ctx.Deadline() + require.True(t, ok) + deadlineSeen <- struct{}{} + <-ctx.Done() + return nil, ctx.Err() + } + + c, err := connectToLogServiceAddresses( + context.Background(), + "", + []string{"first"}, + ClientConfig{}, + ) + require.Error(t, err) + require.ErrorIs(t, err, context.DeadlineExceeded) + require.ErrorIs(t, err, moerr.CauseNewLogServiceClient) + require.Nil(t, c) + select { + case <-deadlineSeen: + default: + t.Fatal("attempt context deadline was not observed") + } +} + +func TestConnectToLogServiceAddressesWithCanceledContextDoesNotDial(t *testing.T) { + origConnect := connectToLogServiceAddressFn + defer func() { + connectToLogServiceAddressFn = origConnect + }() + + called := make(chan struct{}, 1) + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + called <- struct{}{} + return nil, errors.New("unexpected dial") + } + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + c, err := connectToLogServiceAddresses( + ctx, + "", + []string{"first"}, + ClientConfig{}, + ) + require.Error(t, err) + require.ErrorIs(t, err, context.Canceled) + require.Nil(t, c) + select { + case <-called: + t.Fatal("unexpected connection attempt") + default: + } +} + +func TestConnectToLogServiceAddressesReturnsWinnerWithoutWaitingForLoser(t *testing.T) { + origConnect := connectToLogServiceAddressFn + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectFallbackDelay = time.Millisecond + defer func() { + connectToLogServiceAddressFn = origConnect + logServiceConnectFallbackDelay = origFallbackDelay + }() + + firstStarted := make(chan struct{}) + releaseFirst := make(chan struct{}) + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + if addr == "first" { + close(firstStarted) + <-releaseFirst + return nil, errors.New("first failed") + } + return &client{ + client: &closeTrackingRPCClient{ + closeMu: &sync.Mutex{}, + closeCount: new(int), + }, + }, nil + } + + done := make(chan *client, 1) + errs := make(chan error, 1) + go func() { + c, err := connectToLogServiceAddresses( + context.Background(), + "", + []string{"first", "second"}, + ClientConfig{}, + ) + if err != nil { + errs <- err + return + } + done <- c + }() + + <-firstStarted + var c *client + select { + case c = <-done: + case err := <-errs: + require.NoError(t, err) + case <-time.After(100 * time.Millisecond): + t.Fatal("timed out waiting for connection result") + } + require.NotNil(t, c) + require.NoError(t, c.close()) + close(releaseFirst) +} + +func TestConnectToLogServiceAddressesReturnsContextErrorWithoutWaitingForLoser(t *testing.T) { + origConnect := connectToLogServiceAddressFn + defer func() { + connectToLogServiceAddressFn = origConnect + }() + + started := make(chan struct{}) + release := make(chan struct{}) + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + close(started) + <-release + return nil, errors.New("first failed") + } + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + done := make(chan error, 1) + go func() { + c, err := connectToLogServiceAddresses( + ctx, + "", + []string{"first"}, + ClientConfig{}, + ) + require.Nil(t, c) + done <- err + }() + + <-started + select { + case err := <-done: + require.Error(t, err) + require.ErrorIs(t, err, context.DeadlineExceeded) + case <-time.After(100 * time.Millisecond): + t.Fatal("timed out waiting for context error") + } + close(release) +} + +func TestConnectToLogServiceAddressesClosesSuccessfulLosers(t *testing.T) { + origConnect := connectToLogServiceAddressFn + origFallbackDelay := logServiceConnectFallbackDelay + logServiceConnectFallbackDelay = time.Millisecond + defer func() { + connectToLogServiceAddressFn = origConnect + logServiceConnectFallbackDelay = origFallbackDelay + }() + + called := make(chan string, 2) + release := make(chan struct{}) + closeCount := 0 + var closeMu sync.Mutex + connectToLogServiceAddressFn = func( + ctx context.Context, + sid string, + addr string, + cfg ClientConfig, + ) (*client, error) { + called <- addr + select { + case <-release: + case <-ctx.Done(): + return nil, ctx.Err() + } + return &client{ + client: &closeTrackingRPCClient{ + closeMu: &closeMu, + closeCount: &closeCount, + }, + }, nil + } + + done := make(chan *client, 1) + errs := make(chan error, 1) + go func() { + c, err := connectToLogServiceAddresses( + context.Background(), + "", + []string{"first", "second"}, + ClientConfig{}, + ) + if err != nil { + errs <- err + return + } + done <- c + }() + + require.Equal(t, "first", readCalledAddress(t, called)) + require.Equal(t, "second", readCalledAddress(t, called)) + close(release) + + var c *client + select { + case c = <-done: + case err := <-errs: + require.NoError(t, err) + case <-time.After(time.Second): + t.Fatal("timed out waiting for connection result") + } + require.NotNil(t, c) + + require.Eventually(t, func() bool { + closeMu.Lock() + defer closeMu.Unlock() + return closeCount == 1 + }, time.Second, time.Millisecond) + + require.NoError(t, c.close()) + closeMu.Lock() + assert.Equal(t, 2, closeCount) + closeMu.Unlock() +} + +func TestStopConnectFallbackTimer(t *testing.T) { + stopConnectFallbackTimer(nil) + + timer := time.NewTimer(time.Hour) + stopConnectFallbackTimer(timer) + + expired := time.NewTimer(time.Nanosecond) + time.Sleep(time.Millisecond) + stopConnectFallbackTimer(expired) +} + +func readCalledAddress(t *testing.T, called <-chan string) string { + t.Helper() + select { + case addr := <-called: + return addr + case <-time.After(time.Second): + t.Fatal("timed out waiting for connection attempt") + } + return "" +} + +type closeTrackingRPCClient struct { + closeMu *sync.Mutex + closeCount *int +} + +func (c *closeTrackingRPCClient) Send(context.Context, string, morpc.Message) (*morpc.Future, error) { + return nil, errors.New("unexpected send") +} + +func (c *closeTrackingRPCClient) NewStream(string, bool) (morpc.Stream, error) { + return nil, errors.New("unexpected stream") +} + +func (c *closeTrackingRPCClient) Ping(context.Context, string) error { + return errors.New("unexpected ping") +} + +func (c *closeTrackingRPCClient) Close() error { + c.closeMu.Lock() + defer c.closeMu.Unlock() + (*c.closeCount)++ + return nil +} + +func (c *closeTrackingRPCClient) CloseBackend() error { + return nil +} + +func startHangingTCPServer(t *testing.T) (string, func()) { + t.Helper() + ln, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + + done := make(chan struct{}) + var wg sync.WaitGroup + wg.Add(1) + go func() { + defer wg.Done() + for { + conn, err := ln.Accept() + if err != nil { + return + } + wg.Add(1) + go func() { + defer wg.Done() + defer func() { + assert.NoError(t, conn.Close()) + }() + <-done + }() + } + }() + + var once sync.Once + cleanup := func() { + once.Do(func() { + assert.NoError(t, ln.Close()) + close(done) + wg.Wait() + }) + } + return ln.Addr().String(), cleanup +} + func TestClientGetTSOTimestamp(t *testing.T) { fn := func(t *testing.T, s *Service, cfg ClientConfig, c Client) { ctx, cancel := context.WithTimeout(context.Background(), time.Second)