感谢详细的解说。
抱歉,是有其他站点的
timer.at和access_by_lua干扰了,不过那些调用那个和test.lua没关系。所以实际上
test(10000000000) 还是只执行了一次。
这次我把其他站点用的
timer.at的代码和access_by_lua都注掉了,还是报这个错误。我看到日志里面还是有event timer add,应该都是内部的timer了。
==> /site/error.log <==
2014/09/04 10:58:03 [debug] 5576#0: *25 http cl:-1 max:1048576
2014/09/04 10:58:03 [debug] 5576#0: *25 rewrite phase: 3
2014/09/04 10:58:03 [debug] 5576#0: *25 rewrite phase: 4
2014/09/04 10:58:03 [debug] 5576#0: *25 post rewrite phase: 5
2014/09/04 10:58:03 [debug] 5576#0: *25 generic phase: 6
2014/09/04 10:58:03 [debug] 5576#0: *25 generic phase: 7
2014/09/04 10:58:03 [debug] 5576#0: *25 access phase: 8
2014/09/04 10:58:03 [debug] 5576#0: *25 access phase: 9
2014/09/04 10:58:03 [debug] 5576#0: *25 post access phase: 10
2014/09/04 10:58:03 [debug] 5576#0: *25 lua content handler, uri:"/api/1.0/test" c:1
2014/09/04 10:58:03 [debug] 5576#0: *25 add cleanup: 8005D6B0
2014/09/04 10:58:03 [debug] 5576#0: *25 lua creating new vm state
2014/09/04 10:58:03 [debug] 5576#0: *25 lua initializing lua registry
2014/09/04 10:58:03 [debug] 5576#0: *25 lua initializing lua globals
2014/09/04 10:58:03 [debug] 5576#0: *25 lua initialize the global Lua VM FFF301C0
2014/09/04 10:58:03 [debug] 5576#0: *25 malloc: 800678F8:8
2014/09/04 10:58:03 [debug] 5576#0: *25 http script var: "/site"
2014/09/04 10:58:03 [debug] 5576#0: *25 http script copy: "/api/1.0/"
2014/09/04 10:58:03 [debug] 5576#0: *25 http script capture: "test"
2014/09/04 10:58:03 [debug] 5576#0: *25 http script copy: ".lua"
2014/09/04 10:58:03 [debug] 5576#0: *25 lua reset ctx
2014/09/04 10:58:03 [debug] 5576#0: *25 lua creating new thread
2014/09/04 10:58:03 [debug] 5576#0: *25 http cleanup add: 8005D704
2014/09/04 10:58:03 [debug] 5576#0: *25 lua run thread, top:0 c:1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket pool get keepalive peer
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket keepalive connection pool not found
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket connect timeout: 2000
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket network address given directly
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket resolve retval handler
2014/09/04 10:58:03 [debug] 5576#0: *25 socket 6
2014/09/04 10:58:03 [debug] 5576#0: *25 connect to 127.0.0.1:6379, fd:6 #27
2014/09/04 10:58:03 [debug] 5576#0: *25 select add event fd:6 ev:1
2014/09/04 10:58:03 [debug] 5576#0: *25 select add event fd:6 ev:4
2014/09/04 10:58:03 [debug] 5576#0: *25 http cleanup add: 8005D770
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket connect: -2
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer add: 6: 2000:1050212201
2014/09/04 10:58:03 [debug] 5576#0: *25 lua resume returned 1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua thread yielded
2014/09/04 10:58:03 [debug] 5576#0: *25 http finalize request: -4, "/api/1.0/test?" a:1, c:2
2014/09/04 10:58:03 [debug] 5576#0: *25 http request count:2 blk:0
2014/09/04 10:58:03 [debug] 5576#0: *25 post event 8005C0E0
2014/09/04 10:58:03 [debug] 5576#0: *25 delete posted event 8005C0E0
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket handler for "/api/1.0/test?", wev 1
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer del: 6: 1050212201
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket connected
2014/09/04 10:58:03 [debug] 5576#0: *25 select del event fd:6 ev:4
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket waking up the current request (conn)
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp operation done, resuming lua thread
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket calling prepare retvals handler 004A6213, u:FFF18408
2014/09/04 10:58:03 [debug] 5576#0: *25 lua run thread, top:0 c:1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket send timeout: 2000
2014/09/04 10:58:03 [debug] 5576#0: *25 lua allocate new chainlink and new buf of size 39, cl:8005D77C
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket send data
2014/09/04 10:58:03 [debug] 5576#0: *25 send: fd:6 39 of 39
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket sent all the data
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket calling receive() method
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read timeout: 2000
2014/09/04 10:58:03 [debug] 5576#0: *25 lua allocate new chainlink and new buf of size 65536, cl:8005D7E4
2014/09/04 10:58:03 [debug] 5576#0: *25 malloc: 800B1920:65536
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read data: wait:0
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer add: 6: 2000:1050212218
2014/09/04 10:58:03 [debug] 5576#0: *25 lua resume returned 1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua thread yielded
2014/09/04 10:58:03 [debug] 5576#0: *25 lua run thread returned -2
2014/09/04 10:58:03 [debug] 5576#0: *25 post event 800581F8
2014/09/04 10:58:03 [debug] 5576#0: *25 delete posted event 800581F8
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket handler for "/api/1.0/test?", wev 0
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read handler
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer del: 6: 1050212218
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read data: wait:1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket try to recv data 65536: "/api/1.0/test?"
2014/09/04 10:58:03 [debug] 5576#0: *25 recv: fd:6 5 of 65536
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket recv returned 5: "/api/1.0/test?"
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read line
"014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read the final line part: "+OK
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket receive done: wait:1, eof:0, uri:"/api/1.0/test?"
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket waking up the current request (read)
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp operation done, resuming lua thread
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket calling prepare retvals handler 004A79B5, u:FFF18408
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket receive return value handler
2014/09/04 10:58:03 [debug] 5576#0: *25 lua run thread, top:0 c:1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket set keepalive: saving connection 8005A470
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket connection pool size: 100
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket keepalive create connection pool for key "127.0.0.1:6379"
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket clear current socket connection
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket keepalive timeout: 10000 ms
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer add: 6: 10000:1050220219
2014/09/04 10:58:03 [debug] 5576#0: *25 lua finalize socket
==> /site/access.log <==
127.0.0.1 - - [04/Sep/2014:10:58:14 +0800] "GET /api/1.0/test HTTP/1.1" "-" 500 600 "c1f4a1fa86eb930053f96f7a97a091c7" "http://localhost/test/index.html" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebK
it/537.36 (KHTML, like Gecko) Chrome/36.0.1985.143 Safari/537.36"
==> /site/error.log <==
2014/09/04 10:58:03 [notice] 5576#0: *25 [lua] test.lua:150: test(): time 11, client: 127.0.0.1, server: localhost, request: "GET /api/1.0/test HTTP/1.1", host: "localhost", referrer: "http://
localhost/test/index.html"
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket pool get keepalive peer
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket get keepalive peer: using connection 8005A470, fd:6
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer del: 6: 1050220219
2014/09/04 10:58:03 [debug] 5576#0: *25 http cleanup add: 8005D838
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket send timeout: 2000
2014/09/04 10:58:03 [debug] 5576#0: *25 lua reuse free buf memory 39 >= 39, cl:8005D77C, p:8005D7BC
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket send data
2014/09/04 10:58:03 [debug] 5576#0: *25 send: fd:6 39 of 39
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket sent all the data
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket calling receive() method
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read timeout: 2000
2014/09/04 10:58:03 [debug] 5576#0: *25 lua reuse free buf memory 65536 >= 65536, cl:8005D7E4, p:800B1920
2014/09/04 10:58:03 [debug] 5576#0: *25 lua tcp socket read data: wait:0
2014/09/04 10:58:03 [debug] 5576#0: *25 event timer add: 6: 2000:1050212219
2014/09/04 10:58:03 [debug] 5576#0: *25 lua resume returned 1
2014/09/04 10:58:03 [debug] 5576#0: *25 lua thread yielded
2014/09/04 10:58:03 [debug] 5576#0: *25 lua run thread returned -2
2014/09/04 10:58:14 [debug] 5576#0: *25 post event 800581F8
2014/09/04 10:58:14 [debug] 5576#0: *25 event timer del: 6: 1050212219
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket handler for "/api/1.0/test?", wev 0
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket read handler
2014/09/04 10:58:14 [error] 5576#0: *25 lua tcp socket read timed out, client: 127.0.0.1, server: localhost, request: "GET /api/1.0/test HTTP/1.1", host: "localhost", referrer: "http://localho
st/test/index.html"
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket handle read error
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket waking up the current request
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp operation done, resuming lua thread
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket calling prepare retvals handler 004A79B5, u:FFF3E990
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket receive return value handler
2014/09/04 10:58:14 [debug] 5576#0: *25 lua run thread, top:0 c:1
2014/09/04 10:58:14 [debug] 5576#0: *25 lua finalize socket
2014/09/04 10:58:14 [debug] 5576#0: *25 select del event fd:6 ev:1
2014/09/04 10:58:14 [debug] 5576#0: *25 delete posted event 800581F8
2014/09/04 10:58:14 [debug] 5576#0: *25 lua close socket connection
2014/09/04 10:58:14 [debug] 5576#0: *25 reusable connection: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 lua tcp socket keepalive: free connection pool for "127.0.0.1:6379"
2014/09/04 10:58:14 [debug] 5576#0: *25 lua resume returned 2
2014/09/04 10:58:14 [error] 5576#0: *25 lua entry thread aborted: runtime error: /site/api/1.0/test.lua:132: failed to authenticate:timeout
stack traceback:
coroutine 0:
[C]: in function 'error'
/site/api/1.0/test.lua:3: in function 'do_redis_read'
/site/api/1.0/test.lua:37: in function </site/api/1.0/test.lua:1>, client: 127.0.0.1, server: localhost, request: "GET /api/1.0/test HTTP/1.1", host: "localhos
t", referrer: "http://localhost/test/index.html"
2014/09/04 10:58:14 [debug] 5576#0: *25 lua request cleanup: forcible=0
2014/09/04 10:58:14 [debug] 5576#0: *25 lua run thread returned 500
2014/09/04 10:58:14 [debug] 5576#0: *25 http finalize request: 500, "/api/1.0/test?" a:1, c:1
2014/09/04 10:58:14 [debug] 5576#0: *25 http special response: 500, "/api/1.0/test?"
2014/09/04 10:58:14 [debug] 5576#0: *25 http set discard body
2014/09/04 10:58:14 [debug] 5576#0: *25 headers more header filter, uri "/api/1.0/test"
2014/09/04 10:58:14 [debug] 5576#0: *25 lua header filter for user lua code, uri "/api/1.0/test"
2014/09/04 10:58:14 [debug] 5576#0: *25 lua capture header filter, uri "/api/1.0/test"
2014/09/04 10:58:14 [debug] 5576#0: *25 charset: "" > "utf-8"
2014/09/04 10:58:14 [debug] 5576#0: *25 HTTP/1.1 500 Internal Server Error
Date: Thu, 04 Sep 2014 02:58:14 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 600
Connection: close
Server: GameServer_openresty
2014/09/04 10:58:14 [debug] 5576#0: *25 write new buf t:1 f:0 8005D88C, pos 8005D88C, size: 181 file: 0, size: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 http write filter: l:0 f:0 s:181
2014/09/04 10:58:14 [debug] 5576#0: *25 http output filter "/api/1.0/test?"
2014/09/04 10:58:14 [debug] 5576#0: *25 http copy filter: "/api/1.0/test?"
2014/09/04 10:58:14 [debug] 5576#0: *25 lua body filter for user lua code, uri "/api/1.0/test"
2014/09/04 10:58:14 [debug] 5576#0: *25 http cleanup add: 8005DA5C
2014/09/04 10:58:14 [debug] 5576#0: *25 lua capture body filter, uri "/api/1.0/test"
2014/09/04 10:58:14 [debug] 5576#0: *25 http postpone filter "/api/1.0/test?" 8005DA44
2014/09/04 10:58:14 [debug] 5576#0: *25 write old buf t:1 f:0 8005D88C, pos 8005D88C, size: 181 file: 0, size: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 write new buf t:0 f:0 00000000, pos 004CB4A0, size: 140 file: 0, size: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 write new buf t:0 f:0 00000000, pos 004CC660, size: 58 file: 0, size: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 write new buf t:0 f:0 00000000, pos 004CC480, size: 402 file: 0, size: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 http write filter: l:1 f:0 s:781
2014/09/04 10:58:14 [debug] 5576#0: *25 http write filter limit 0
2014/09/04 10:58:14 [debug] 5576#0: *25 writev: 781
2014/09/04 10:58:14 [debug] 5576#0: *25 http write filter 00000000
2014/09/04 10:58:14 [debug] 5576#0: *25 http copy filter: 0 "/api/1.0/test?"
2014/09/04 10:58:14 [debug] 5576#0: *25 http finalize request: 0, "/api/1.0/test?" a:1, c:1
2014/09/04 10:58:14 [debug] 5576#0: *25 http request count:1 blk:0
2014/09/04 10:58:14 [debug] 5576#0: *25 http close request
2014/09/04 10:58:14 [debug] 5576#0: *25 lua request cleanup: forcible=0
2014/09/04 10:58:14 [debug] 5576#0: *25 http log handler
2014/09/04 10:58:14 [debug] 5576#0: *25 parse header: "Cookie: JSESSIONID=215D25F47F6D74E6D1F787BD52AC17A6; session=c1f4a1fa86eb930053f96f7a97a091c7"
2014/09/04 10:58:14 [debug] 5576#0: *25 run cleanup: 8005D6B0
2014/09/04 10:58:14 [debug] 5576#0: *25 free: 800B1920
2014/09/04 10:58:14 [debug] 5576#0: *25 free: 8005CCB0, unused: 269
2014/09/04 10:58:14 [debug] 5576#0: *25 close http connection: 4
2014/09/04 10:58:14 [debug] 5576#0: *25 select del event fd:4 ev:1
2014/09/04 10:58:14 [debug] 5576#0: *25 reusable connection: 0
2014/09/04 10:58:14 [debug] 5576#0: *25 free: 80059268
2014/09/04 10:58:14 [debug] 5576#0: *25 free: 80067910, unused: 36