search

osmfj / tileman

Renamed from tilecache to "tileman": please re-config your git repository. This is OpenStreetMap "Tile-cache" and "Tile-server" recipe with Nginx and embeded Lua. A backend is Tirex, mapnik and PostGIS.
http://osm.jp/
61 stars 16 forks source link

nginx-lua fail to communicate thru unix domain sokcet datagram #22

Closed miurahr closed 11 years ago

miurahr commented 11 years ago

nginx debug log:

2013/04/27 09:44:27 [debug] 17551#0: *1977 event timer del: 10: 1367023527926
2013/04/27 09:44:27 [debug] 17551#0: *1977 generic phase: 0
2013/04/27 09:44:27 [debug] 17551#0: *1977 rewrite phase: 1
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script value: "0"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script set $x
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script value: "0"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script set $y
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script value: "0"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script set $z
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script value: "0"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script set $minz
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script value: "18"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script set $maxz
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script value: "custom"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http script set $map
2013/04/27 09:44:27 [debug] 17551#0: *1977 test location: "/"
2013/04/27 09:44:27 [debug] 17551#0: *1977 test location: "robots.txt"
2013/04/27 09:44:27 [debug] 17551#0: *1977 test location: "favicon.ico"
2013/04/27 09:44:27 [debug] 17551#0: *1977 using configuration "/"
2013/04/27 09:44:27 [debug] 17551#0: *1977 http cl:-1 max:1048576
2013/04/27 09:44:27 [debug] 17551#0: *1977 rewrite phase: 3
2013/04/27 09:44:27 [debug] 17551#0: *1977 rewrite phase: 4
2013/04/27 09:44:27 [debug] 17551#0: *1977 post rewrite phase: 5
2013/04/27 09:44:27 [debug] 17551#0: *1977 generic phase: 6
2013/04/27 09:44:27 [debug] 17551#0: *1977 generic phase: 7
2013/04/27 09:44:27 [debug] 17551#0: *1977 generic phase: 8
2013/04/27 09:44:27 [debug] 17551#0: *1977 access phase: 9
2013/04/27 09:44:27 [debug] 17551#0: *1977 access phase: 10
2013/04/27 09:44:27 [debug] 17551#0: *1977 access phase: 11
2013/04/27 09:44:27 [debug] 17551#0: *1977 access phase: 12
2013/04/27 09:44:27 [debug] 17551#0: *1977 access phase: 13
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua access handler, uri:"/6/57/24.png" c:1
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua creating new thread
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua reset ctx
2013/04/27 09:44:27 [debug] 17551#0: *1977 http cleanup add: 0000000001EFF210
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua run thread, top:0 c:1
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua resume returned 0
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua light thread ended normally
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua deleting light thread
2013/04/27 09:44:27 [debug] 17551#0: *1977 post access phase: 14
2013/04/27 09:44:27 [debug] 17551#0: *1977 try files phase: 15
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua content handler, uri:"/6/57/24.png" c:1
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua reset ctx
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua creating new thread
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua run thread, top:0 c:1
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket network address given directly
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket resolve retval handler
2013/04/27 09:44:27 [debug] 17551#0: *1977 UDP socket 25
2013/04/27 09:44:27 [debug] 17551#0: *1977 datagram unix domain socket autobind
2013/04/27 09:44:27 [debug] 17551#0: *1977 connect to unix:/var/run/tirex/master.sock, fd:25 #1978
2013/04/27 09:44:27 [debug] 17551#0: *1977 epoll add event: fd:25 op:1 ev:80000001
2013/04/27 09:44:27 [debug] 17551#0: *1977 http cleanup add: 0000000001EFF360
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket connect: 0
2013/04/27 09:44:27 [debug] 17551#0: *1977 [lua] tileserver.lua:172: send_tile_tirex(): tirex req: map=custom
type=metatile_enqueue_request
z=6
id=luats-8
y=24
x=56
prio=8

2013/04/27 09:44:27 [debug] 17551#0: *1977 send: fd:25 73 of 73
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket calling receive() method
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket read timeout: 1000
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket receive buffer size: 8192
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket read data: waiting: 0
2013/04/27 09:44:27 [debug] 17551#0: *1977 recv: fd:25 -1 of 8192
2013/04/27 09:44:27 [debug] 17551#0: *1977 recv() not ready (11: Resource temporarily unavailable)
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp recv returned -2
2013/04/27 09:44:27 [debug] 17551#0: *1977 event timer add: 25: 1000:1367023468927
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua resume returned 1
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua thread yielded
2013/04/27 09:44:27 [debug] 17551#0: *1977 http finalize request: -4, "/6/57/24.png?" a:1, c:2
2013/04/27 09:44:27 [debug] 17551#0: *1977 http request count:2 blk:0
2013/04/27 09:44:28 [debug] 17551#0: *1977 event timer del: 25: 1367023468927
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket handler for "/6/57/24.png?", wev 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket read handler
2013/04/27 09:44:28 [error] 17551#0: *1977 lua udp socket read timed out, client: 125.30.23.86, server: tile.openstreetmap.jp, request: "GET /6/57/24.png HTTP/1.1", host: "tile.openstreetmap.jp"
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket handle error
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket waking up the current request
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp operation done, resuming lua thread
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket calling prepare retvals handler 00000000004D8D00, u:0000000001F045F8
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket receive return value handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket error retval handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua run thread, top:0 c:1
2013/04/27 09:44:28 [error] 17551#0: *1977 [lua] tileserver.lua:181: send_tile_tirex(): tirex: Command reply error: timeout, client: 125.30.23.86, server: tile.openstreetmap.jp, request: "GET /6/57/24.png HTTP/1.1", host: "tile.openstreetmap.jp"
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua exit with code 500
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua resume returned 1
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua thread yielded
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua thread aborting request with status 500
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua request cleanup
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua run thread returned 500
2013/04/27 09:44:28 [debug] 17551#0: *1977 http finalize request: 500, "/6/57/24.png?" a:1, c:1
2013/04/27 09:44:28 [debug] 17551#0: *1977 http special response: 500, "/6/57/24.png?"
2013/04/27 09:44:28 [debug] 17551#0: *1977 http set discard body
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua capture header filter, uri "/6/57/24.png"
2013/04/27 09:44:28 [debug] 17551#0: *1977 uploadprogress error-tracker error: 500
2013/04/27 09:44:28 [debug] 17551#0: *1977 uploadprogress error-tracker not tracking in this location
2013/04/27 09:44:28 [debug] 17551#0: *1977 xslt filter header
2013/04/27 09:44:28 [debug] 17551#0: *1977 posix_memalign: 0000000001F0CC00:4096 @16
2013/04/27 09:44:28 [debug] 17551#0: *1977 HTTP/1.1 500 Internal Server Error
Server: nginx/1.2.8
Date: Sat, 27 Apr 2013 00:44:28 GMT
Content-Type: text/html
Content-Length: 192
Connection: close

2013/04/27 09:44:28 [debug] 17551#0: *1977 write new buf t:1 f:0 0000000001F0CC20, pos 0000000001F0CC20, size: 161 file: 0, size: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 http write filter: l:0 f:0 s:161
2013/04/27 09:44:28 [debug] 17551#0: *1977 http output filter "/6/57/24.png?"
2013/04/27 09:44:28 [debug] 17551#0: *1977 http copy filter: "/6/57/24.png?"
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua capture body filter, uri "/6/57/24.png"
2013/04/27 09:44:28 [debug] 17551#0: *1977 image filter
2013/04/27 09:44:28 [debug] 17551#0: *1977 xslt filter body
2013/04/27 09:44:28 [debug] 17551#0: *1977 http postpone filter "/6/57/24.png?" 0000000001F0CDF0
2013/04/27 09:44:28 [debug] 17551#0: *1977 write old buf t:1 f:0 0000000001F0CC20, pos 0000000001F0CC20, size: 161 file: 0, size: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 write new buf t:0 f:0 0000000000000000, pos 0000000000725600, size: 140 file: 0, size: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 write new buf t:0 f:0 0000000000000000, pos 0000000000724500, size: 52 file: 0, size: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 http write filter: l:1 f:0 s:353
2013/04/27 09:44:28 [debug] 17551#0: *1977 http write filter limit 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 writev: 353
2013/04/27 09:44:28 [debug] 17551#0: *1977 http write filter 0000000000000000
2013/04/27 09:44:28 [debug] 17551#0: *1977 http copy filter: 0 "/6/57/24.png?"
2013/04/27 09:44:28 [debug] 17551#0: *1977 http finalize request: 0, "/6/57/24.png?" a:1, c:1
2013/04/27 09:44:28 [debug] 17551#0: *1977 event timer add: 10: 5000:1367023473929
2013/04/27 09:44:28 [debug] 17551#0: *1977 http lingering close handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 recv: fd:10 -1 of 4096
2013/04/27 09:44:28 [debug] 17551#0: *1977 recv() not ready (11: Resource temporarily unavailable)
2013/04/27 09:44:28 [debug] 17551#0: *1977 lingering read: -2
2013/04/27 09:44:28 [debug] 17551#0: *1977 event timer: 10, old: 1367023473929, new: 1367023473929
2013/04/27 09:44:28 [debug] 17551#0: *1977 post event 0000000001ECC478
2013/04/27 09:44:28 [debug] 17551#0: *1977 delete posted event 0000000001ECC478
2013/04/27 09:44:28 [debug] 17551#0: *1977 http lingering close handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 recv: fd:10 0 of 4096
2013/04/27 09:44:28 [debug] 17551#0: *1977 lingering read: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 http request count:1 blk:0
2013/04/27 09:44:28 [debug] 17551#0: *1977 http close request
2013/04/27 09:44:28 [debug] 17551#0: *1977 cleanup lua udp socket upstream request: "/6/57/24.png"
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua finalize socket
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua close socket connection
2013/04/27 09:44:28 [debug] 17551#0: *1977 reusable connection: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 http log handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 free: 0000000001EFE3D0, unused: 8
2013/04/27 09:44:28 [debug] 17551#0: *1977 free: 0000000001F0CC00, unused: 3337
2013/04/27 09:44:28 [debug] 17551#0: *1977 close http connection: 10
2013/04/27 09:44:28 [debug] 17551#0: *1977 event timer del: 10: 1367023473929
2013/04/27 09:44:28 [debug] 17551#0: *1977 reusable connection: 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 free: 0000000001EF3FE0
2013/04/27 09:44:28 [debug] 17551#0: *1977 free: 0000000001F05F60
2013/04/27 09:44:28 [debug] 17551#0: *1977 free: 0000000001E8E7A0, unused: 8
2013/04/27 09:44:28 [debug] 17551#0: *1977 free: 0000000001E8C060, unused: 128
miurahr commented 11 years ago

Here is a problem point:

call udpsocket:receive()

2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket calling receive() method
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket read timeout: 1000
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket receive buffer size: 8192
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp socket read data: waiting: 0
2013/04/27 09:44:27 [debug] 17551#0: *1977 recv: fd:25 -1 of 8192
2013/04/27 09:44:27 [debug] 17551#0: *1977 recv() not ready (11: Resource temporarily unavailable)

got recv() -EAGAIN

2013/04/27 09:44:27 [debug] 17551#0: *1977 lua udp recv returned -2

Immediately reterun -2

2013/04/27 09:44:27 [debug] 17551#0: *1977 event timer add: 25: 1000:1367023468927
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua resume returned 1
2013/04/27 09:44:27 [debug] 17551#0: *1977 lua thread yielded
2013/04/27 09:44:27 [debug] 17551#0: *1977 http finalize request: -4, "/6/57/24.png?" a:1, c:2
2013/04/27 09:44:27 [debug] 17551#0: *1977 http request count:2 blk:0
2013/04/27 09:44:28 [debug] 17551#0: *1977 event timer del: 25: 1367023468927

Timeout without call again

2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket handler for "/6/57/24.png?", wev 0
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket read handler
2013/04/27 09:44:28 [error] 17551#0: *1977 lua udp socket read timed out, client: 125.30.23.86, server: tile.openstreetmap.jp, request: "GET /6/57/24.png HTTP/1.1", host: "tile.openstreetmap.jp"
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket handle error
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket waking up the current request
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp operation done, resuming lua thread
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket calling prepare retvals handler 00000000004D8D00, u:0000000001F045F8
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket receive return value handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua udp socket error retval handler
2013/04/27 09:44:28 [debug] 17551#0: *1977 lua run thread, top:0 c:1
2013/04/27 09:44:28 [error] 17551#0: *1977 [lua] tileserver.lua:181: send_tile_tirex(): tirex: Command reply error: timeout, client: 125.30.23.86, server: tile.openstreetmap.jp, request: "GET /6/57/24.png HTTP/1.1", host: "tile.openstreetmap.jp"

got error in tileserver LUA code.

2013/04/27 09:44:28 [debug] 17551#0: *1977 lua exit with code 500

return 500 lastly