Re: negative size buf in writer после writev() not ready

[Maxim Dounin]

Hello!

On Sun, Nov 24, 2019 at 06:45:32PM -0500, kron wrote:

> Доброго всем дня!
> Сейчас в процессе написания модуля для nginx по генерации PDF
> (https://github.com/undying/nginx-html2x-module/blob/master/src/ngx_http_html2x_module.c#L205)
> и наткнулся в процессе на странное.
> Началось с того, что если тестировать локально, то генерация и отдача PDF
> работает.
> Если разнести сервер и клиента на разные машины, начинаются проблемы.
> 
> В логе нашел следующее:
> 2019/11/24 23:22:31 [debug] 9#9: *1 http write filter limit 0
> 2019/11/24 23:22:31 [debug] 9#9: *1 writev: 44540 of 168186
> 2019/11/24 23:22:31 [debug] 9#9: *1 writev: -1 of 123646
> 
> 2019/11/24 23:22:31 [debug] 9#9: *1 writev() not ready (11: Resource
> temporarily unavailable)
> 
> 2019/11/24 23:22:31 [debug] 9#9: *1 http write filter 000055D3FDBEFF60
> 2019/11/24 23:22:31 [debug] 9#9: *1 http copy filter: -2
> "/html2pdf?dpi=100"
> 2019/11/24 23:22:31 [debug] 9#9: *1 http finalize request: -2,
> "/html2pdf?dpi=100" a:1, c:1
> 2019/11/24 23:22:31 [debug] 9#9: *1 event timer add: 3: 60000:1302169663
> 2019/11/24 23:22:31 [debug] 9#9: *1 epoll add event: fd:3 op:3 ev:80002005
> 2019/11/24 23:22:32 [debug] 9#9: *1 http run request: "/html2pdf?dpi=100"
> 2019/11/24 23:22:32 [debug] 9#9: *1 http writer handler:
> "/html2pdf?dpi=100"
> 2019/11/24 23:22:32 [debug] 9#9: *1 http output filter "/html2pdf?dpi=100"
> 2019/11/24 23:22:32 [debug] 9#9: *1 http copy filter: "/html2pdf?dpi=100"
> 2019/11/24 23:22:32 [debug] 9#9: *1 write old buf t:0 f:0 00007FFFC360B460,
> pos 0000000000000000, size: 1254989623795351808 file: 94368983417552, size:
> -94368983417552
> 
> 2019/11/24 23:22:32 [alert] 9#9: *1 negative size buf in writer t:0 r:0 f:0
> 00007FFFC360B460 0000000000000000-116A9E69E31F8100 000055D3FDBBFF00
> 94368983417552-0, client: 192.168.1.228, server: , request: "POST
> /html2pdf?dpi=100 HTTP/1.1", host: "html2x.domain.local"
> 
> 2019/11/24 23:22:32 [debug] 9#9: *1 http copy filter: -1
> "/html2pdf?dpi=100"
> 2019/11/24 23:22:32 [debug] 9#9: *1 http writer output filter: -1,
> "/html2pdf?dpi=100"
> 
> Насколько я понял, после первой пачки байт сокет становится занят и запись
> откладывается, но с наступлением таймера, при повторной попытке записи
> оказывается, что буфер для чтения пуст.
> Пока не понял, почему так может быть. Был бы благодарен за любую подсказку.

У вас буфер, который вы отдаёте в ngx_http_output_filter() - на 
стеке.  Соответственно если содержимое буфера не отправляется 
сразу - при следующей попытке по соответствующему указателю будет 
уже не буфер, а мусор.  Именно это наглядно демострирует 
приведённый вами лог.

Не надо так.  На стеке можно держать chain link'и (ngx_chain_t), а 
вот структуры буферов (ngx_buf_t) и собственно сами данные - 
обязательно должны иметь время жизни не меньше, чем требуется для 
их отправки клиенту.  То есть в простейшем случае - их следует 
выделять из пула запроса.

-- 
Maxim Dounin
http://mdounin.ru/