bug: WARN server/server.go:59 key not found

[spacewander]

@envestcc

Could you log down the token & conf with the given patch?

diff --git internal/plugin/conf.go internal/plugin/conf.go
index 5758f0a..9f67c59 100644
--- internal/plugin/conf.go
+++ internal/plugin/conf.go
@@ -129,10 +129,12 @@ func (cc *ConfCache) SetInTest(token uint32, entries RuleConf) error {
 }

 func (cc *ConfCache) Get(token uint32) (RuleConf, error) {
+       log.Warnf("get conf with token %d", token)
        res, err := cc.tokenCache.Get(strconv.FormatInt(int64(token), 10))
        if err != nil {
                return nil, err
        }
+       log.Warnf("conf result with token %v", res.(RuleConf))
        return res.(RuleConf), err
 }

For apisix:

diff --git apisix/plugins/ext-plugin/init.lua apisix/plugins/ext-plugin/init.lua
index 6cb593c8..a43228c1 100644
--- apisix/plugins/ext-plugin/init.lua
+++ apisix/plugins/ext-plugin/init.lua
@@ -358,6 +358,8 @@ local rpc_handlers = {
             return nil, err
         end

+        core.log.warn("get conf token: ", token, " conf: ", core.json.delay_encode(conf.conf))
+
         builder:Clear()
         local var = ctx.var

And how to reproduce this issue?

[envestcc]

i don't known how to reproduce this issue yet. I also found this problem by accident.

[spacewander]

@envestcc
Does #44 solve the problem?

[envestcc]

i don't known how to reproduce this issue yet. I also found this problem by accident.

the log is here:

2021/10/09 10:49:49 [warn] 6123#6123: *13162642 [lua] init.lua:361: get conf token: 1 conf: [{"value":"","name":"auth_check"}], client: 10.192.233.18, server: _, request: "GET /welcome HTTP/1.1", host: ""
2021/10/09 10:49:49 [warn] 6126#6126: *343 [lua] init.lua:683: 2021-10-09T10:49:49.431+0800	INFO	server/server.go:121	receive rpc type: 2 data length: 896
, context: ngx.timer
2021/10/09 10:49:49 [warn] 6126#6126: *343 [lua] init.lua:683: 2021-10-09T10:49:49.431+0800	WARN	plugin/conf.go:132	get conf with token 1
2021-10-09T10:49:49.431+0800	WARN	server/server.go:59	key not found
, context: ngx.timer

[envestcc]

@envestcc Does #44 solve the problem?

No, "key not found" is still shown.

btw, where can i set or see the token expire time in apisix ?

[spacewander]

It is set in https://github.com/apache/apisix/blob/03a1c760845e7666d924b4f817a42e8e4c0c7e0b/apisix/plugins/ext-plugin/init.lua#L639

[envestcc]

Any other ideas?

[spacewander]

Err, we need a way to reproduce it so that we can locate it. Can you find a way to reproduce it?

[zdzh]

lrucache should be set invalid_stale = true?

local events_list
local lrucache = core.lrucache.new({
    type = "plugin",
    ttl = helper.get_conf_token_cache_time(),
})

local function new_lru_fun(opts)
    ...
    local item_release = opts and opts.release
    local invalid_stale = opts and opts.invalid_stale    -- false
    local serial_creating = opts and opts.serial_creating
    local lru_obj = lru_new(item_count)

    return function (key, version, create_obj_fun, ...)
        if not serial_creating or not can_yield_phases[get_phase()] then
            local cache_obj = fetch_valid_cache(lru_obj, invalid_stale,
                                item_ttl, item_release, key, version)
            if cache_obj then
                return cache_obj.val
            end
   .....

local function fetch_valid_cache(lru_obj, invalid_stale, item_ttl,
                                 item_release, key, version)
    local obj, stale_obj = lru_obj:get(key)
    if obj and obj.ver == version then
        return obj
    end

    -- get an expired key in lrucachd  that could not find in go runner
    if not invalid_stale and stale_obj and stale_obj.ver == version then
        lru_obj:set(key, stale_obj, item_ttl)
        return stale_obj
    end

    if item_release and obj then  
        item_release(obj.val)
    end

    return nil
end

[spacewander]

@zdzh
You are correct! Would you submit a fix to APISIX?

[spacewander]

Fixed by apache/apisix#5309

[spacewander]

apache/apisix#5782
Fix this issue more thoroughly. When the token key in the cache doesn't match the conf in the runner (probably in the dev mode, after people restart the runner), a new lrucache will be created. This lrucache hasn't invalid stale cache until this PR fixes it.