bug: attempt to index local 'item' (a boolean value)

[cloorc]

Current Behavior

Newly installed apisix cluster throws following exception:

2023/01/10 10:03:19 [error] 54#54: *1312995 [lua] config_etcd.lua:662: failed to fetch data from etcd: /usr/local/apisix/apisix/core/config_util.lua:99: attempt to index local 'item' (a boolean value)
stack traceback:
        /usr/local/apisix/apisix/core/config_util.lua:99: in function 'fire_all_clean_handlers'
        /usr/local/apisix/apisix/core/config_etcd.lua:379: in function 'sync_data'
        /usr/local/apisix/apisix/core/config_etcd.lua:609: in function </usr/local/apisix/apisix/core/config_etcd.lua:599>
        [C]: in function 'xpcall'
        /usr/local/apisix/apisix/core/config_etcd.lua:599: in function </usr/local/apisix/apisix/core/config_etcd.lua:577>,  etcd key: /apisix/routes, context: ngx.timer

Expected Behavior

Running without former issue.

Error Logs

2023/01/10 10:06:21 [error] 48#48: *1334880 [lua] config_etcd.lua:662: failed to fetch data from etcd: /usr/local/apisix/apisix/core/config_util.lua:99: attempt to index local 'item' (a boolean value)
stack traceback:
/usr/local/apisix/apisix/core/config_util.lua:99: in function 'fire_all_clean_handlers'
/usr/local/apisix/apisix/core/config_etcd.lua:379: in function 'sync_data'
/usr/local/apisix/apisix/core/config_etcd.lua:609: in function </usr/local/apisix/apisix/core/config_etcd.lua:599>
[C]: in function 'xpcall'
/usr/local/apisix/apisix/core/config_etcd.lua:599: in function </usr/local/apisix/apisix/core/config_etcd.lua:577>, etcd key: /apisix/routes, context: ngx.timer
2023/01/10 10:06:21 [error] 50#50: *1334917 [lua] config_etcd.lua:662: failed to fetch data from etcd: /usr/local/apisix/apisix/core/config_util.lua:99: attempt to index local 'item' (a boolean value)
stack traceback:
/usr/local/apisix/apisix/core/config_util.lua:99: in function 'fire_all_clean_handlers'
/usr/local/apisix/apisix/core/config_etcd.lua:379: in function 'sync_data'
/usr/local/apisix/apisix/core/config_etcd.lua:609: in function </usr/local/apisix/apisix/core/config_etcd.lua:599>
[C]: in function 'xpcall'
/usr/local/apisix/apisix/core/config_etcd.lua:599: in function </usr/local/apisix/apisix/core/config_etcd.lua:577>, etcd key: /apisix/routes, context: ngx.timer
2023/01/10 10:06:22 [error] 56#56: *1334983 [lua] config_etcd.lua:662: failed to fetch data from etcd: /usr/local/apisix/apisix/core/config_util.lua:99: attempt to index local 'item' (a boolean value)
stack traceback:
/usr/local/apisix/apisix/core/config_util.lua:99: in function 'fire_all_clean_handlers'
/usr/local/apisix/apisix/core/config_etcd.lua:379: in function 'sync_data'
/usr/local/apisix/apisix/core/config_etcd.lua:609: in function </usr/local/apisix/apisix/core/config_etcd.lua:599>
[C]: in function 'xpcall'
/usr/local/apisix/apisix/core/config_etcd.lua:599: in function </usr/local/apisix/apisix/core/config_etcd.lua:577>, etcd key: /apisix/routes, context: ngx.timer

Steps to Reproduce

1. Install apisix cluster with following images: apache/apisix:3.1.0-debian
2. Running at least 4 hours;
3. Not sure this issue will be throwed as previous.

Environment

• APISIX version (run apisix version): 3.1.0 (3.1.0-debian official docker image)
• Operating system (run uname -a): Linux apisix-v3-0-58d694d79d-8567j 4.4.0-210-generic update the doc of https for Chinese version. #242-Ubuntu SMP Fri Apr 16 09:57:56 UTC 2021 x86_64 GNU/Linux
• OpenResty / Nginx version (run openresty -V or nginx -V): nginx version: openresty/1.21.4.1
• etcd version, if relevant (run curl http://127.0.0.1:9090/v1/server_info): {"boot_time":1672910773,"etcd_version":"3.4.0","hostname":"apisix-v3-0-58d694d79d-8567j","version":"3.1.0","id":"c978a662-9041-4e7b-9a4d-d5bea6ef32f9"}
• APISIX Dashboard version, if relevant:
• Plugin runner version, for issues related to plugin runners:
• LuaRocks version, for installation issues (run luarocks --version):

[tokers]

@cloorc Did you see any error log entries before these kinds of errors? I think this error is not the "primary crime scene". Also, is it possible to print the data in your ETCD?

[cloorc]

@cloorc Did you see any error log entries before these kinds of errors? I think this error is not the "primary crime scene". Also, is it possible to print the data in your ETCD?

ETCD works fine. And what may results in this issue? I've no any thoughts about this issue.

[tokers]

@cloorc Did you see any error log entries before these kinds of errors? I think this error is not the "primary crime scene". Also, is it possible to print the data in your ETCD?

ETCD works fine. And what may results in this issue? I've no any thoughts about this issue.

I have no idea because I cannot reproduce this issue.

[Liu-Junlin]

I often encounter this problem and need to restart apisix server to recover

[cloorc]

I often encounter this problem and need to restart apisix server to recover

I guess it could be resulted from compaction(or related operations) of etcd.

[zsmlinux]

I often encounter this problem and need to restart apisix server to recover

How much your apisixserver's memory using?

I also have met many times, and I found apisixserver's memory is full last time.

[basuotian]

similar to #8492 ?
related to etcd compaction

[zsmlinux]

similar to #8492 ? related to etcd compaction

I think …… yes

[oyiadin]

We've reproduced it in our test env steadily, by inserting and deleting apisix resources while an etcd compaction occurred. And the issue will keep on exist until we restart apisix mannually. So I dive into the source code and find a weired spot:

apisix/apisix/core/config_etcd.lua

Lines 392 to 401 in e4e7c73

	if not dir_res then
	if err == "compacted" then
	self.need_reload = true
	log.warn("waitdir [", self.key, "] err: ", err,
	", will read the configuration again via readdir")
	return false
	end
	return false, err
	end

Line#397 returns a "false" while no "err" is provided. And the caller of this function checks err only:

apisix/apisix/core/config_etcd.lua

Lines 606 to 607 in e021266

	local ok, err = sync_data(self)
	if err then

After changing this line to return false, err, we cannot reproduce the issue anymore with the exactly same way of inserting and deleting while etcd compaction.

But i have no time to reproduce it with minimal step way right now.

[spacewander]

Line#397 returns a "false" while no "err" is provided.

It's intended. So that the sync will be reentered with self.need_reload = true. See

apisix/apisix/core/config_etcd.lua

Lines 651 to 653 in 02421e2

	elseif not ok then
	-- no error. reentry the sync with different state
	ngx_sleep(0.05)