背景
最近正在开发关于WebService相关系统,其中有两个模块使用的是(nginx+lua)框架,业务逻辑用lua语言实现。而从这两个新模块上线到正常运行,一共发生了两次请求错乱的线上问题:
1
2
3query A: http:://uriA + argsA
在经过proxy(or webui)这一层处理之后,请求传到下一层module变成了queryB,导致请求错乱,影响线上服务。
query B: http:://uriB + argsB
第一次踩坑&&追查过程(proxy):
首先确定入口请求的URL A,经过proxy处理之后,NOTICE日志打印的URL,发现前后的URL不一致,怀疑是经过某个module之后,URL被篡改。同时这种现象一般发生在*前后时间比较靠近的请求之间 ***。
线上一台proxy机器打开一台nginx debug日志(注意:日志很大,所以时间不能太长),发现了一个比较诡异的现象:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
2010:22:42 [debug] 3505#0: *1 lua upstream: B64A2168
10:22:42 [debug] 3505#0: *2 lua upstream: B71D5FF8
10:22:42 [debug] 3505#0: *1 lua upstream: B64A2168
10:22:42 [debug] 3505#0: *2 lua upstream: B71D5FF8
10:22:42 [debug] 3505#0: *1 lua upstream: B64A2168
10:22:42 [debug] 3505#0: *1 lua upstream: B64A2168 <===
10:22:42 [debug] 3505#0: *2 lua upstream: B71D5FF8
10:22:42 [debug] 3505#0: *2 lua upstream: B71D5FF8
10:22:42 [debug] 3505#0: *1 lua upstream: B71D5FF8 <===
10:22:42 [debug] 3505#0: *2 lua upstream: B71D5FF8
10:29:23 [debug] 3505#0: *5 lua upstream: B64B0A20
10:29:23 [debug] 3505#0: *6 lua upstream: B64B0FA8
10:29:23 [debug] 3505#0: *5 lua upstream: B64B0A20
10:29:23 [debug] 3505#0: *6 lua upstream: B64B0FA8
10:29:23 [debug] 3505#0: *5 lua upstream: B64B0A20
10:29:23 [debug] 3505#0: *5 lua upstream: B64B0A20
10:29:23 [debug] 3505#0: *6 lua upstream: B64B0FA8
10:29:23 [debug] 3505#0: *6 lua upstream: B64B0FA8
10:29:23 [debug] 3505#0: *5 lua upstream: B64B0A20
10:29:23 [debug] 3505#0: *6 lua upstream: B64B0FA8两个箭头指向的都是req1,但是前后的upstream pointer确发生了改变,第二个箭头表明req1使用了upstream pointer “B71D5FF8”,但是这个pointer这时候req2正在使用,这时候我们觉得很可能是upstream pointer的改变,导致了URL被篡改(也就是reqA -> reqB),但是是什么原因导致upstream pointer改变一时还没有什么头绪。
这时候想到了openresty google group和github openresty issue,想看看有没有遇到类似异常情况的。
发现有一个帖子It seems the socket upstream pointer changed while processing concurrent requests.有点类似我们的情况,仔细看了一下帖子,楼主和春哥的结论是lua global variable不当使用,造成意外的跨请求socket共享,导致异常出现。使用lua-releng脚本check我们的proxy代码发现:
飘红的地方使用了非预期的全局变量,改成local之后,小流量上线验证,不再出现请求错乱的情况。
lua全局变量官方说明
关于lua变量的作用域,官方文档说明: lua-variable-scope
1 | Generally, use of Lua global variables is a really really bad idea in the context of ngx_lua because |
官方说明:在并发场景下,一些应该使用局部变量的地方如果滥用lua的全局变量可能会导致一些异常的情况出现; 同时全局变量的访问开销代价很大;如果出错很难调试。
第二次踩坑(ui module)
经过第一次的经验,我们已经将proxy 和 ui 代码进行了全量的check,修复所有非预期的全局变量的使用。
但是,ui上线切新的流量之后,一些服务又出现请求错乱的问题,查看日志发现同一个logid的请求,URL前后又出现不一致情况,并且重试的情况下,有概率的出现。
当时,第一感觉是全局变量问题,但是我们线上的代码已经用lua-releng脚本check过了,并未有非local变量的情况。
追查过程:
- 因为这次上线是首次使用action/InnerRedirect.lua模块,所以我们的检查重点放在这个module中。
- 有一个涉及全局变量的地方引起了我们的注意:
飘红的箭头是一个全局的配置,而Conf_Services是一个全局变量,但是这里是赋值给local变量service,而service变量在下面的地方进行了修改:
1
2
service.url = path
service.args = args
相当于我们把一个全局变量赋值给一个已经申明为local的变量,然后直接对这个local table变量进行修改。
这个地方有点怀疑这个**local table变量service,在用全局变量赋值的时候使用的是浅拷贝**,为了验证我们的怀疑,写了下面一个非常简单的lua test script:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
table_global = {
["key1"] = "key1",
["key2"] = "key2",
["key3"] = "key3",
}
print("global table address: ")
print(table_global)
local tmp_table = table_global
print("local table address: ")
print(tmp_table)
tmp_table["key3"] = "key333"
print("After modidy local table field: ")
print(table_global["key3"])
TEST RESULT:
global table address:
table: 0x539de0
local table address:
table: 0x539de0
After modidy local table field:
key333
更改此处service使用全局配置的方式:
上线一台机器出现缩略图错乱的线上机器,不再出现URL被篡改情况。
而刚才说的只有在第一次请求失败之后,重试才会出现错乱,是因为:在第二次重试的时候,代码逻辑中的
compare_str
条件才为true
,service变量被赋值,因为在重试的时候会出现引入全局变量。lua 中的table使用的是*引用方式 ***,这个大家都清楚,但是
table的拷贝是浅拷贝
,如果我们在代码不得己需要使用全局的配置,赋值给一个local table,同时在后续的逻辑中更改了这个local table,就有可能会出现引入全局变量的情况。
总结
lua中的全局变量使用需谨慎,可以使用 lua-releng-tool 脚本check非预期的global variable,尽量使用local 申明变量。
对于一些全局的Conf,不得不使用全局变量的时候,在table 赋值引用的时候,需要进行特殊处理(例如上面的坑二处理方式)。或者使用clone的方式,进行深拷贝赋值(lua-clone)。
后续对新上传SVN的代码都需要使用lua-releng脚本进行check;
同时,在引用全局配置的时候都需要使用特殊方式处理,防止异常case。