Locker context deadline exceeded

[lenonqing]

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]

GetWriteTimeout=10s

[rueian]

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:

https://github.com/redis/rueidis/blob/25821d0444e88e344cd27e66d7c9b4f27da7c580/rueidislock/lock.go#L84-L95

[lenonqing]

OK,Thanks!

[lenonqing]

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"

[rueian]

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]

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]

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

[rueian]

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

[rueian]

Hi @lenonqing, did you find more details?

[lenonqing]

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

[lenonqing]

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]

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

[rueian]

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

[rueian]

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

[lenonqing]

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

[lenonqing]

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]

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]

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]

I think it is caused by some race between lockerCancel() and the upcoming WithContext(). I have tried better handling it at: https://github.com/redis/rueidis/pull/669 and v1.0.50-alpha.3.

Could you try v1.0.50-alpha.3?

[lenonqing]

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

[rueian]

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]

OK

[lenonqing]

HI,have a panic

[rueian]

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]

200+ goroutines

[rueian]

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]

@rueian Yes, run on x86 platform.

[rueian]

@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?