"zero size buf in writer" error happens sometimes when get a file (the size is 500M) from OpenResty(with proxy cache, and slice size 2m),and read data from redis in rewrite_by_lua_file().

[gwy8868]

• version:

  openresty-1.9.15.1
  

• nginx error log:

  [alert] 1607#0: *1 zero size buf in writer t:1 r:0 f:0 00007FC75D5526D8 00007FC75D5526D8-00007FC75D5526D8 0000000000000000 0-0 while sending to client, client: 127.0.0.1, server: , request: "GET http://blog.qihooyun.cn/500M_019.apk HTTP/1.1", subrequest: "/500M_019.apk", upstream: "http://127.0.0.1:8080/500M_019.apk", host: "blog.qihooyun.cn"
  

• I trace it and find that:

  1. nginx worker calls ngx_http_write_filter() to send data in ngx_chain_t to client, but not completed, left some chains in r->main->out.
  
  2. lua thread runs code in rewrite_by_lua_file() and read data from redis.
  
  3. nginx worker calls ngx_http_lua_rewrite_handler() and ngx_http_lua_wev_handler() and ngx_http_lua_flush_pending_output() to send a special chain and buf(chain->buf->flush is 1, chain->buf->temporary is 0),
  
      calls ngx_http_write_filter() to send data in ngx_chain_t to client, but not completed again, left some chains that include the special (copied) chain and (same) buf in r->main->out,
  
      frees the chain to ctx->free_bufs, but the buf is still in r->main->out, not be sent.
  
  4. lua thread runs code in rewrite_by_lua_file() and read data from redis, in the process, lua thread get chain and buf which is same to privious from ctx->free_bufs, and modify chain->buf->temporary from 0 to 1, and realloc buf->start.
  
  5. nginx worker call ngx_http_write_filter() to send data in ngx_chain_t to client, checkout the chain and buf(chain->buf->temporary is 1) in r->out, find it is not a special again.
  
  6. so get the error "zero size buf in writer".
  

• debug log:

the address of special chain is 00007FC75D92F010,
the address of start in special buf is 00007FC75D5525E8,
the address of realloced start in special buf is 00007FC75D5526D8

  ......
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp operation done, resuming lua thread
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket calling prepare retvals handler 00000000005448F9, u:00000000412756B0
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua run thread, top:0 c:2
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket send timeout: 3000
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua allocate new chainlink and new buf of size 23, cl:00007FC75D92F010
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua socket tcp_nodelay
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket send data
  2017/03/20 15:45:34 [debug] 1607#0: *1 send: fd:22 23 of 23
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket sent all the data
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket calling receive() method
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket read timeout: 3000
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua allocate new chainlink and new buf of size 4096, cl:00007FC75D92EFB0
  2017/03/20 15:45:34 [debug] 1607#0: *1 malloc: 00007FC75D658080:4096
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket read data: wait:0
  2017/03/20 15:45:34 [debug] 1607#0: *1 event timer add: 22: 3000:1489995937863
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua resume returned 1
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua thread yielded
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua run thread returned -2
  2017/03/20 15:45:34 [debug] 1607#0: timer delta: 1
  2017/03/20 15:45:34 [debug] 1607#0: *1 event timer del: 18: 1489995934863
  2017/03/20 15:45:34 [debug] 1607#0: *1 http run request: "/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 rewrite phase: 5
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua rewrite handler, uri:"/500M_019.apk" c:2
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua run write event handler: timedout:1, ready:1, writing_raw_req_socket:0
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua flushing output: buffered 0x10
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua reuse free buf memory 23 >= 0, cl:00007FC75D92F010, p:00007FC75D5525E8
  2017/03/20 15:45:34 [debug] 1607#0: *1 http output filter "/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 http copy filter: "/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua capture body filter, uri "/500M_019.apk"
  2017/03/20 15:45:34 [debug] 1607#0: *1 image filter
  2017/03/20 15:45:34 [debug] 1607#0: *1 http postpone filter "/500M_019.apk?" 00007FC75D92F010
  2017/03/20 15:45:34 [debug] 1607#0: *1 write old buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 65536, size: 2032209
  2017/03/20 15:45:34 [debug] 1607#0: *1 write old buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
  2017/03/20 15:45:34 [debug] 1607#0: *1 write new buf t:0 f:0 00007FC75D5525E8, pos 00007FC75D5525E8, size: 0 file: 0, size: 0
  2017/03/20 15:45:34 [debug] 1607#0: *1 http write filter: l:0 f:1 s:2032209
  2017/03/20 15:45:34 [debug] 1607#0: *1 http write filter limit 131072
  2017/03/20 15:45:34 [debug] 1607#0: *1 sendfile: 131072 of 131072 @65536
  2017/03/20 15:45:34 [debug] 1607#0: *1 http write filter 00007FC75D9330B0
  2017/03/20 15:45:34 [debug] 1607#0: *1 event timer add: 18: 1:1489995934864
  2017/03/20 15:45:34 [debug] 1607#0: *1 http copy filter: -2 "/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 useless lua write event handler
  2017/03/20 15:45:34 [debug] 1607#0: worker cycle
  2017/03/20 15:45:34 [debug] 1607#0: epoll timer: 1
  2017/03/20 15:45:34 [debug] 1607#0: epoll: fd:22 ev:0005 d:00007FC64C9F77F0
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket handler for "/500M_019.apk?", wev 0
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket read handler
  2017/03/20 15:45:34 [debug] 1607#0: *1 event timer del: 22: 1489995937863
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket read data: wait:1
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket try to recv data 4096: "/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 recv: fd:22 5 of 4096
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket recv returned 5: "/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket read line
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket read the final line part: "+OK
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket receive done: wait:1, eof:0, uri:"/500M_019.apk?"
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket waking up the current request (read)
  2017/03/20 15:45:34 [debug] 1607#0: *1 rewrite phase: 5
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua rewrite handler, uri:"/500M_019.apk" c:2
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp operation done, resuming lua thread
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket calling prepare retvals handler 000000000054696D, u:00000000412756B0
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket receive return value handler
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua run thread, top:0 c:2
  2017/03/20 15:45:34 [debug] 1607#0: *1 [lua] dl_redis.lua:18: new_redis(): host:127.0.0.1:6379 db:2
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket send timeout: 3000
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua reuse free buf chain, but reallocate memory because 35 >= 23, cl:00007FC75D92F010, p:00007FC75D5525E8
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket send data
  2017/03/20 15:45:34 [debug] 1607#0: *1 send: fd:22 35 of 35
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket sent all the data
  2017/03/20 15:45:34 [debug] 1607#0: *1 lua tcp socket calling receive() method
  ......
  2017/03/20 15:45:55 [debug] 1607#0: *1 write old buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 196608, size: 1901137
  2017/03/20 15:45:55 [debug] 1607#0: *1 write old buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
  2017/03/20 15:45:55 [debug] 1607#0: *1 write old buf t:1 f:0 00007FC75D5526D8, pos 00007FC75D5526D8, size: 0 file: 0, size: 0
  2017/03/20 15:45:55 [alert] 1607#0: *1 zero size buf in writer t:1 r:0 f:0 00007FC75D5526D8 00007FC75D5526D8-00007FC75D5526D8 0000000000000000 0-0 while sending to client, client: 127.0.0.1, server: , request: "GET http://blog.qihooyun.cn/500M_019.apk HTTP/1.1", subrequest: "/500M_019.apk", upstream: "http://127.0.0.1:8080/500M_019.apk", host: "blog.qihooyun.cn"
  ......

[agentzh]

@gwy8868 I don't think it's related. The rewrite_by_lua_file directive runs in the rewrite phase, and it should never generate any data to the client. So your analysis just does not make any sense. You mixed two separate request running phases of nginx, the rewrite phase and the content phase. I believe your error message is from the content phase, where there is no ngx_lua code running at all (unless you use body_filter_by_lua*).

[agentzh]

@gwy8868 It looks more like an issue in the nginx slice and proxy modules.

[deadpig8]

i have got a same problem? Do U fix it?

[spacewander]

@gwy8868

frees the chain to ctx->free_bufs, but the buf is still in r->main->out, not be sent.

It is quite strange to reuse a unsent buffer, since ngx_chain_update_chains will stop reusing the chain once there is a buffer with non-zero size.

The debug log shows us that there is an old buffer with size 2032209. Could you tell us more details about this buffer?

It will be great if you could offer us a reproducible test case.

[eaufavor]

We encountered the same issue. When the slice feature is used, the lua tcp socket code in the rewrite phase of the subrequest picks a free buffer but the same buffer is somehow still in use in the main request's output chain.

The issue was gone when we disabled the free buf reuse here.

Our set up is complicated but I think the triggering conditions are

• large file with caching and slice enabled
• lua tcp socket IO in the rewrite phase of subreuquests.

[zhuizhuhaomeng]

@eaufavor Which version of OpenResty are you using now ?
We have fixed a problem like this one.

[setnicka]

I encountered a similar problem, this is still present on master. ngx_http_lua_get_flush_chain() takes the flush buffer from ctx->free_bufs and leaves the module tag on it, so ngx_chain_update_chains() returns it to the free list while the write filter still has it queued.

@gwy8868's analysis holds. Two details worth adding:

• ngx_buf_special() is derived from the flags, not stored, so memzeroing a recycled buffer silently strips the property while the writer still points at it.
• ngx_chain_update_chains() only recycles buffers whose tag matches, so the tag is what exposes the flush buffer in the first place.

It is not only an alert: the write filter returns NGX_ERROR, so the request is terminated and the response truncated.

We hit this on a caching reverse proxy with Lua cosockets in the rewrite phase, and confirmed the sequence with debug logging enabled: buffers returned to ctx->free_bufs while still linked in r->out.

Could this be reopened? I already prepared a fix in #2518.