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

Locker context deadline exceeded #653

Open
lenonqing opened this issue Oct 25, 2024 · 29 comments
Open

Locker context deadline exceeded #653

lenonqing opened this issue Oct 25, 2024 · 29 comments

Comments

@lenonqing
Copy link

lenonqing commented Oct 25, 2024

version: v1.0.47

const fallbackSETPXVersion = "6.2.0"


type wrapLocker struct {
	v ConfInterface
	rueidislock.Locker
}

func (w *wrapLocker) wrap(ctx context.Context, name string, f func(ctx context.Context, name string) (context.Context, context.CancelFunc, error)) (context.Context, context.CancelFunc, error) {
	if _, ok := ctx.Deadline(); ok {
		return f(ctx, name)
	}
	ctx0, cancel0 := context.WithTimeout(ctx, w.v.GetWriteTimeout())
	ctx1, cancel1, err := f(ctx0, name)
	return ctx1, func() {
		if cancel1 != nil {
			cancel1()
		}
		cancel0()
	}, err
}

func (w *wrapLocker) WithContext(ctx context.Context, name string) (context.Context, context.CancelFunc, error) {
	return w.wrap(ctx, name, w.Locker.WithContext)
}

// TryWithContext tries to acquire a distributed redis lock by name without waiting. It may return ErrNotLocked.
func (w *wrapLocker) TryWithContext(ctx context.Context, name string) (context.Context, context.CancelFunc, error) {
	return w.wrap(ctx, name, w.Locker.TryWithContext)
}

// ForceWithContext takes over a distributed redis lock by canceling the original holder. It may return ErrNotLocked.
func (w *wrapLocker) ForceWithContext(ctx context.Context, name string) (context.Context, context.CancelFunc, error) {
	return w.wrap(ctx, name, w.Locker.ForceWithContext)
}

func newLocker(c *client, opts ...LockerOption) (Locker, error) {
	if c.version.LessThan(mustNewSemVersion(fallbackSETPXVersion)) {
		opts = append(opts, WithLockerOptionFallbackSETPX(true))
	}
	cc := newLockerOptions(opts...)
	l, err := rueidislock.NewLocker(rueidislock.LockerOption{
		KeyPrefix:      cc.GetKeyPrefix(),
		KeyValidity:    cc.GetKeyValidity(),
		TryNextAfter:   cc.GetTryNextAfter(),
		KeyMajority:    cc.GetKeyMajority(),
		NoLoopTracking: cc.GetNoLoopTracking(),
		FallbackSETPX:  cc.GetFallbackSETPX(),
		ClientOption:   confVisitor2ClientOption(c.v),
		ClientBuilder: func(option rueidis.ClientOption) (rueidis.Client, error) {
			return c.cmd, nil
		},
	})
	if err != nil {
		return nil, err
	}
	return &wrapLocker{Locker: l, v: c.v}, nil
}

func (c *client) NewLocker(opts ...LockerOption) (Locker, error) {
	return newLocker(c, opts...)
}

test code:

func TestName(t *testing.T) {
    c := MustNewClient(newDefaultConf())
    locker, err := c.NewLocker(WithLockerOptionKeyMajority(1))
    if err != nil {
         t.Fatal(err)
    }

    for {
         doWithLocker(t, locker)
         time.Sleep(2 * time.Second)
    }
}

func doWithLocker(t *testing.T, locker Locker) {
    now := time.Now()
    _, cancel, err := locker.WithContext(context.Background(), "aaaaaa")
    if err != nil {
        t.Fatal(err, time.Since(now))
    }
    cancel()
}

rueidis/rueidislock/lock.go

func (m *locker) WithContext(src context.Context, name string) (context.Context, context.CancelFunc, error) {
	for {
		ctx, cancel := context.WithCancel(src)
		g, err := m.waitgate(ctx, name)
		if g != nil {
			if cancel, err := m.try(ctx, cancel, name, g, false); err == nil {
				return ctx, cancel, nil
			}
			m.mu.Lock()
			g.w-- // do not delete g from m.gates here.
			m.mu.Unlock()
		} else {
			fmt.Println("---get g-----")
		}
		if cancel(); err != nil {
			return ctx, cancel, err
		}
	}
}

output:

=== RUN   TestName
---get g-----
    xxx_test.go:26: context deadline exceeded 10.00166825s
--- FAIL: TestName (2440.39s)

FAIL
@lenonqing
Copy link
Author

GetWriteTimeout=10s

@rueian
Copy link
Collaborator

rueian commented Oct 25, 2024

Hi @lenonqing,

You can't return an existing client in the ClientBuilder. You must use the option passed to it to create a new client because there are some important settings that can't be ignored:

if option.ClientOption.DisableCache {
impl.noloop = true
impl.nocsc = true
} else {
if option.NoLoopTracking {
option.ClientOption.ClientTrackingOptions = []string{"OPTOUT", "NOLOOP"}
} else {
option.ClientOption.ClientTrackingOptions = []string{"OPTOUT"}
}
option.ClientOption.OnInvalidations = impl.onInvalidations
}
option.ClientOption.PipelineMultiplex = -1 // this ensures the CSC goes to the same connection.

@lenonqing
Copy link
Author

OK,Thanks!

@lenonqing
Copy link
Author

lenonqing commented Oct 28, 2024

NewLocker use a new Redis client, however, there are still some requests(very few) that cannot obtain locks.

I cannot get the key of locker from Redis when obtain failed.

func newLocker(c *client, opts ...LockerOption) (Locker, error) {
	if c.version.LessThan(mustNewSemVersion(fallbackSETPXVersion)) {
		opts = append(opts, WithLockerOptionFallbackSETPX(true))
	}
	cc := newLockerOptions(opts...)
	l, err := rueidislock.NewLocker(rueidislock.LockerOption{
		KeyPrefix:      cc.GetKeyPrefix(),
		KeyValidity:    cc.GetKeyValidity(),
		TryNextAfter:   cc.GetTryNextAfter(),
		KeyMajority:    cc.GetKeyMajority(),
		NoLoopTracking: cc.GetNoLoopTracking(),
		FallbackSETPX:  cc.GetFallbackSETPX(),
		ClientOption:   confVisitor2ClientOption(c.v),
		ClientBuilder: func(option rueidis.ClientOption) (rueidis.Client, error) {
			return rueidis.NewClient(option)
		},
	})
	if err != nil {
		return nil, err
	}
	return &wrapLocker{Locker: l, v: c.v}, nil
}
lockerCtx, lockerCancel, err := redis.Locker.WithContext(ctx, lockerName)
if err != nil {
	var exists bool
	var ttl time.Duration
	val := redis.Client.Exists(ctx, lockerName).Val()
	if exists = val > 0; exists {
		ttl = redis.Client.PTTL(ctx, lockerName).Val()
	}
	err = errors.WrapError(err, "acquire fid lock error, name: %v, uid: %d, locker_name: %s, ke_exists: %v, key_ttl: %s", name, id, lockerName, exists, ttl)
	return lockerCtx, lockerCancel, err
}

log:
"error":"acquire fid lock error, name: room_close, uid: 63347223, locker_name: locker:room_close:{63347223}, key_exists: false, key_ttl: 0s: context deadline exceeded"

@lenonqing lenonqing reopened this Oct 28, 2024
@rueian
Copy link
Collaborator

rueian commented Oct 28, 2024

There is no key stored under the lockerName. They will be rueidislock:0:lockerName, rueidislock:1:lockerName, rueidislock:2:lockerName and so on depending on your KeyMajority.

What does your full LockerOption look like?

@lenonqing
Copy link
Author

There is no key stored under the lockerName. They will be rueidislock:0:lockerName, rueidislock:1:lockerName, rueidislock:2:lockerName and so on depending on your KeyMajority.

What does your full LockerOption look like?

const (
	defaultKeyPrefix      = "redislock"
	defaultKeyValidity    = 5 * time.Second
	defaultExtendInterval = 1 * time.Second
	defaultTryNextAfter   = 20 * time.Millisecond
	defaultKeyMajority    = int32(2)
)

//go:generate optiongen --option_with_struct_name=true --new_func=newLockerOptions --empty_composite_nil=true --usage_tag_name=usage
func LockerOptionsOptionDeclareWithDefault() any {
	return map[string]any{
		// annotation@KeyPrefix(KeyPrefix is the prefix of redis key for locks. Default value is defaultKeyPrefix)
		"KeyPrefix": string(defaultKeyPrefix),
		// annotation@KeyValidity(KeyValidity is the validity duration of locks and will be extended periodically by the ExtendInterval. Default value is defaultKeyValidity)
		"KeyValidity": time.Duration(defaultKeyValidity),
		// annotation@TryNextAfter(TryNextAfter is the timeout duration before trying the next redis key for locks. Default value is defaultTryNextAfter)
		"TryNextAfter": time.Duration(defaultTryNextAfter),
		// annotation@KeyMajority(KeyMajority is at least how many redis keys in a total of KeyMajority*2-1 should be acquired to be a valid lock. Default value is defaultKeyMajority)
		"KeyMajority": int32(defaultKeyMajority),
		// annotation@NoLoopTracking(NoLoopTracking will use NOLOOP in the CLIENT TRACKING command to avoid unnecessary notifications and thus have better performance. This can only be enabled if all your redis nodes >= 7.0.5)
		"NoLoopTracking": false,
		// annotation@FallbackSETPX(Use SET PX instead of SET PXAT when acquiring locks to be compatible with Redis < 6.2)
		"FallbackSETPX": false,
	}
}

NewLocker(redisson.WithLockerOptionKeyMajority(1))

@lenonqing
Copy link
Author

I should check if "rueidislock: 0: lockerName" exists?Because "KeyMajority" is 1.

@rueian
Copy link
Collaborator

rueian commented Oct 28, 2024

You changed the KeyPrefix, so it should be redislock:0:locker:room_close:{63347223}.

@rueian
Copy link
Collaborator

rueian commented Oct 31, 2024

Hi @lenonqing, did you find more details?

@lenonqing
Copy link
Author

I have the latest logs when next service upgrade.If has result, I will inform you promptly.

@lenonqing
Copy link
Author

lenonqing commented Nov 12, 2024

fs := make([]logbus.Field, 0, 4)
fs = append(fs, logbus.String("name", name), logbus.Uint64("id", id), logbus.String("locker_name", lockerName), logbus.String("source", source))
logbus.Info("want to acquire locker from redis", fs...)

lockerCtx, lockerCancel, err := redis.Locker.WithContext(ctx, lockerName)
if err != nil {
    var exists bool
    var ttl time.Duration
    fullLockerName := fmt.Sprintf("redislock:0:%s", lockerName)
    val := redis.Client.Exists(ctx, fullLockerName).Val()
    if exists = val > 0; exists {
        ttl = redis.Client.PTTL(ctx, fullLockerName).Val()
    }
    err = errors.WrapError(err, "acquire lock error, name: %v, uid: %d, source: %s, locker_name: %s, exists: %v, ttl: %s", name, id, source, lockerName, exists, ttl)
    return lockerCtx, lockerCancel, err
}
game_202411120209_0.log:{"log_level":"info","date":"2024-11-12T02:09:52.653Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbhs73h19lgjihhrtg","server_id":"csom9hv3h19lgjkkrlb0","server_ip":"","server_birth":1731290311,"host_name":"game-7b8bbd9fb7-dzh52","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120214_0.log:{"log_level":"info","date":"2024-11-12T02:14:23.024Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbjvt787lb3s94gka0","server_id":"csom9lt787lb3saokd20","server_ip":"","server_birth":1731290327,"host_name":"game-7b8bbd9fb7-q46rl","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120216_0.log:{"log_level":"info","date":"2024-11-12T02:16:40.320Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbl273h19lgjik0lgg","server_id":"csom9hv3h19lgjkkrlb0","server_ip":"","server_birth":1731290311,"host_name":"game-7b8bbd9fb7-dzh52","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120218_0.log:{"log_level":"info","date":"2024-11-12T02:18:40.972Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbm02jbpejce8jca40","server_id":"csom9dajbpejcebbv4s0","server_ip":"","server_birth":1731290293,"host_name":"game-7b8bbd9fb7-bpvwz","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120219_0.log:{"log_level":"info","date":"2024-11-12T02:19:20.659Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbma4upplq5cboef4g","server_id":"csp9l6cupplq5caeh6m0","server_ip":"","server_birth":1731369625,"host_name":"game-7b8bbd9fb7-m4n8n","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120220_0.log:{"log_level":"info","date":"2024-11-12T02:20:13.957Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbmnd787l00ja8h9i0","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120221_0.log:{"log_level":"info","date":"2024-11-12T02:21:28.970Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbna73h19lgjilivlg","server_id":"csom9hv3h19lgjkkrlb0","server_ip":"","server_birth":1731290311,"host_name":"game-7b8bbd9fb7-dzh52","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120223_0.log:{"log_level":"info","date":"2024-11-12T02:23:12.667Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbo45787lb3s972pk0","server_id":"csom9lt787lb3saokd20","server_ip":"","server_birth":1731290327,"host_name":"game-7b8bbd9fb7-q46rl","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120233_0.log:{"log_level":"info","date":"2024-11-12T02:33:20.892Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbss5787l00jad0g70","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120236_0.log:{"log_level":"info","date":"2024-11-12T02:36:19.002Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbu8qjbpejce8pgf60","server_id":"csom9dajbpejcebbv4s0","server_ip":"","server_birth":1731290293,"host_name":"game-7b8bbd9fb7-bpvwz","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120237_0.log:{"log_level":"info","date":"2024-11-12T02:37:48.702Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbuv5787l00jaeifqg","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120239_0.log:{"log_level":"info","date":"2024-11-12T02:39:47.256Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbvssupplq5cbvrhkg","server_id":"csp9l6cupplq5caeh6m0","server_ip":"","server_birth":1731369625,"host_name":"game-7b8bbd9fb7-m4n8n","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120241_0.log:{"log_level":"info","date":"2024-11-12T02:41:44.864Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspc0q5787l00jag407g","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
"log_level":"error","date":"2024-11-12T02:20:16.958Z","log_xid":"cspbmo5787l00ja8hqgg","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","error":"acquire lock error, name: mail, uid: 35020382, source: FetchMail, locker_name: locker:{mail}:{35020382}, exists: false, ttl: 0s: context deadline exceeded"

@lenonqing
Copy link
Author

@rueian locker key not exists, but acquire locker failure possible

@rueian
Copy link
Collaborator

rueian commented Nov 12, 2024

Hi @lenonqing, is there any deadline associated with your ctx? How long is it? Is there any concurrent access to the same key?

@rueian
Copy link
Collaborator

rueian commented Nov 12, 2024

It will be helpful if you have all request logs from redis.

@lenonqing
Copy link
Author

@rueian yes, has deadline for context, 3 second will cancel for deadline exceeded.

@lenonqing
Copy link
Author

fs := make([]logbus.Field, 0, 4)
fs = append(fs, logbus.String("name", name), logbus.Uint64("id", id), logbus.String("locker_name", lockerName), logbus.String("source", source))
logbus.Info("want to acquire locker from redis", fs...)

lockerCtx, lockerCancel, err := redis.Locker.WithContext(ctx, lockerName)
if err != nil {
    var exists bool
    var ttl time.Duration
    fullLockerName := fmt.Sprintf("redislock:0:%s", lockerName)
    val := redis.Client.Exists(ctx, fullLockerName).Val()
    if exists = val > 0; exists {
        ttl = redis.Client.PTTL(ctx, fullLockerName).Val()
    }
    err = errors.WrapError(err, "acquire lock error, name: %v, uid: %d, source: %s, locker_name: %s, exists: %v, ttl: %s", name, id, source, lockerName, exists, ttl)
    return lockerCtx, lockerCancel, err
}
game_202411120209_0.log:{"log_level":"info","date":"2024-11-12T02:09:52.653Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbhs73h19lgjihhrtg","server_id":"csom9hv3h19lgjkkrlb0","server_ip":"","server_birth":1731290311,"host_name":"game-7b8bbd9fb7-dzh52","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120214_0.log:{"log_level":"info","date":"2024-11-12T02:14:23.024Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbjvt787lb3s94gka0","server_id":"csom9lt787lb3saokd20","server_ip":"","server_birth":1731290327,"host_name":"game-7b8bbd9fb7-q46rl","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120216_0.log:{"log_level":"info","date":"2024-11-12T02:16:40.320Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbl273h19lgjik0lgg","server_id":"csom9hv3h19lgjkkrlb0","server_ip":"","server_birth":1731290311,"host_name":"game-7b8bbd9fb7-dzh52","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120218_0.log:{"log_level":"info","date":"2024-11-12T02:18:40.972Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbm02jbpejce8jca40","server_id":"csom9dajbpejcebbv4s0","server_ip":"","server_birth":1731290293,"host_name":"game-7b8bbd9fb7-bpvwz","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120219_0.log:{"log_level":"info","date":"2024-11-12T02:19:20.659Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbma4upplq5cboef4g","server_id":"csp9l6cupplq5caeh6m0","server_ip":"","server_birth":1731369625,"host_name":"game-7b8bbd9fb7-m4n8n","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120220_0.log:{"log_level":"info","date":"2024-11-12T02:20:13.957Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbmnd787l00ja8h9i0","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120221_0.log:{"log_level":"info","date":"2024-11-12T02:21:28.970Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbna73h19lgjilivlg","server_id":"csom9hv3h19lgjkkrlb0","server_ip":"","server_birth":1731290311,"host_name":"game-7b8bbd9fb7-dzh52","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120223_0.log:{"log_level":"info","date":"2024-11-12T02:23:12.667Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbo45787lb3s972pk0","server_id":"csom9lt787lb3saokd20","server_ip":"","server_birth":1731290327,"host_name":"game-7b8bbd9fb7-q46rl","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120233_0.log:{"log_level":"info","date":"2024-11-12T02:33:20.892Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbss5787l00jad0g70","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120236_0.log:{"log_level":"info","date":"2024-11-12T02:36:19.002Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbu8qjbpejce8pgf60","server_id":"csom9dajbpejcebbv4s0","server_ip":"","server_birth":1731290293,"host_name":"game-7b8bbd9fb7-bpvwz","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120237_0.log:{"log_level":"info","date":"2024-11-12T02:37:48.702Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbuv5787l00jaeifqg","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120239_0.log:{"log_level":"info","date":"2024-11-12T02:39:47.256Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspbvssupplq5cbvrhkg","server_id":"csp9l6cupplq5caeh6m0","server_ip":"","server_birth":1731369625,"host_name":"game-7b8bbd9fb7-m4n8n","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
game_202411120241_0.log:{"log_level":"info","date":"2024-11-12T02:41:44.864Z","dd_meta_channel":"server","tags":"logbus","log_xid":"cspc0q5787l00jag407g","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","name":"mail","id":35020382,"locker_name":"locker:{mail}:{35020382}","source":"FetchMail","message":"want to acquire locker from redis"}
"log_level":"error","date":"2024-11-12T02:20:16.958Z","log_xid":"cspbmo5787l00ja8hqgg","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","error":"acquire lock error, name: mail, uid: 35020382, source: FetchMail, locker_name: locker:{mail}:{35020382}, exists: false, ttl: 0s: context deadline exceeded"

No concurrent access, i update the log

@rueian
Copy link
Collaborator

rueian commented Nov 12, 2024

Are these all the logs related to the locker:{mail}:{35020382}? Do you have multiple servers? Is the following error the only error you observed?

"log_level":"error","date":"2024-11-12T02:20:16.958Z","log_xid":"cspbmo5787l00ja8hqgg","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","error":"acquire lock error, name: mail, uid: 35020382, source: FetchMail, locker_name: locker:{mail}:{35020382}, exists: false, ttl: 0s: context deadline exceeded"

@lenonqing
Copy link
Author

Are these all the logs related to the locker:{mail}:{35020382}? Do you have multiple servers? Is the following error the only error you observed?

"log_level":"error","date":"2024-11-12T02:20:16.958Z","log_xid":"cspbmo5787l00ja8hqgg","server_id":"csom9d5787l00jblhh10","server_ip":"","server_birth":1731290292,"host_name":"game-7b8bbd9fb7-6xnvs","error":"acquire lock error, name: mail, uid: 35020382, source: FetchMail, locker_name: locker:{mail}:{35020382}, exists: false, ttl: 0s: context deadline exceeded"

yes, have only error, have multiple servers, but not have concurrent access this key

@rueian
Copy link
Collaborator

rueian commented Nov 12, 2024

I think it is caused by some race between lockerCancel() and the upcoming WithContext(). I have tried better handling it at: #669 and v1.0.50-alpha.3.

Could you try v1.0.50-alpha.3?

@lenonqing
Copy link
Author

OK,But we need to wait for the next update of the server.

@rueian
Copy link
Collaborator

rueian commented Nov 12, 2024

Hi @lenonqing, please use v1.0.50-alpha.4 instead. It fixes a lock validity extension issue introduced in v1.0.50-alpha.3

@lenonqing
Copy link
Author

OK

@lenonqing
Copy link
Author

HI,have a panic

image

@rueian
Copy link
Collaborator

rueian commented Nov 20, 2024

Hi @lenonqing,

Was that happened on v1.0.50-alpha.4? The only information I found related to the panic is it indicates there are too many goroutines waiting for the fd to be available. Do you know how many goroutines you had at that time? Or, do you have the full goroutines dump at the time?

@lenonqing
Copy link
Author

200+ goroutines

@rueian
Copy link
Collaborator

rueian commented Nov 21, 2024

200+ goroutines shouldn't be a problem to a fd according to https://stackoverflow.com/questions/44678216/panic-net-inconsistent-fdmutex.

Did your application run on x86 platform?

@lenonqing
Copy link
Author

@rueian Yes, run on x86 platform.

@rueian
Copy link
Collaborator

rueian commented Nov 21, 2024

@rueian Yes, run on x86 platform.

Thanks for the confirmation. However, currently, I can't think of what situation can cause the panic. Did it happen on on v1.0.50-alpha.4? Would you be able to capture a goroutine dump when it happens next time?

@lenonqing
Copy link
Author

Current version is v1.0.47,The online server has not upgraded yet.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants