Re: ошибка "upstream prematurely closed connection" - обсудим ?
пн, 14 окт. 2019 г. в 18:09, Maxim Dounin : > Hello! > > On Sun, Oct 13, 2019 at 02:18:30PM +0500, Илья Шипицин wrote: > > > привет, > > > > предыстория. видим ошибку в логах. вспоминаем концепцию, что с уровнем > > error логируются ошибки на стороне сервера. считаем, что ошибка > > действительно была. идем к клиенту - у клиента статус 200, ему хорошо, > все, > > что он хотел считать, он вычитал. повторяем несколько раз, в большинстве > > случаев ситуация повторяется, в логах ошибка, у клиента все хорошо. > > > > ок. идем смотреть исходники > > > > вывод сообщения об ошибке встречается три раза > > > > ./nginx-1.17.4/src/http/ngx_http_upstream.c: > > "upstream prematurely closed connection"); > > ./nginx-1.17.4/src/http/ngx_http_upstream.c: > >"upstream prematurely closed connection"); > > ./nginx-1.17.4/src/http/ngx_http_upstream.c: > > "upstream prematurely closed connection"); > > > > в двух случаях запрос завершается статусом 502 > > > > ngx_http_upstream_finalize_request(r, u, NGX_HTTP_BAD_GATEWAY); > > > > > > в одном месте - не завершается: > > http://hg.nginx.org/nginx/file/tip/src/http/ngx_http_upstream.c#l2369 > > Да, если ошибка происходит при чтении заголовка ответа - nginx > пробует перейти к следующему бэкенду, так как это ещё возможно. > Что, однако же, не означает, что ошибки нет - она есть. > по наблюдаемой картинке - да, похоже, в этом дело и было. получаем 0 из recv во время чтения заголовков, запрос переотправляется, в целом он получается успешный > > > собственно, recv в некоторых случаях может выдавать 0 и это не всегда > > ошибка (у нас CentOS 7, возможно, там какая-то своя магия еще, с > > какими-нибудь сетевыми штуками бекпортированными в ядро 3.10) > > > > man recv > > ... > > "The value 0 may also be returned if the requested number of bytes to > > receive from a stream socket was 0." > > > > собственно, в этом месте меняем текст. и, чудо, после этого > залогированные > > "upstream prematurely closed connection" идеально кореллируют с реальными > > обрывами. > > > > вопрос - в этом месте действительно стоит логировать ошибку с таким > текстом > > ? может поменять уровень на info (или debug), а текст сделать что-то типа > > "zero bytes read from recv" ? > > Если recv() возвращает 0 байт - в предположении, что буфер был не > нулевого размера - то это означает, что соединение закрыто "той > стороной". Если это происходит в момент времени, не > предусмотренный протоколом - то это ошибка, и она логгируется > соответственно. > > -- > Maxim Dounin > http://mdounin.ru/ > ___ > nginx-ru mailing list > nginx-ru@nginx.org > http://mailman.nginx.org/mailman/listinfo/nginx-ru ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: ошибка "upstream prematurely closed connection" - обсудим ?
Hello! On Sun, Oct 13, 2019 at 02:18:30PM +0500, Илья Шипицин wrote: > привет, > > предыстория. видим ошибку в логах. вспоминаем концепцию, что с уровнем > error логируются ошибки на стороне сервера. считаем, что ошибка > действительно была. идем к клиенту - у клиента статус 200, ему хорошо, все, > что он хотел считать, он вычитал. повторяем несколько раз, в большинстве > случаев ситуация повторяется, в логах ошибка, у клиента все хорошо. > > ок. идем смотреть исходники > > вывод сообщения об ошибке встречается три раза > > ./nginx-1.17.4/src/http/ngx_http_upstream.c: > "upstream prematurely closed connection"); > ./nginx-1.17.4/src/http/ngx_http_upstream.c: >"upstream prematurely closed connection"); > ./nginx-1.17.4/src/http/ngx_http_upstream.c: > "upstream prematurely closed connection"); > > в двух случаях запрос завершается статусом 502 > > ngx_http_upstream_finalize_request(r, u, NGX_HTTP_BAD_GATEWAY); > > > в одном месте - не завершается: > http://hg.nginx.org/nginx/file/tip/src/http/ngx_http_upstream.c#l2369 Да, если ошибка происходит при чтении заголовка ответа - nginx пробует перейти к следующему бэкенду, так как это ещё возможно. Что, однако же, не означает, что ошибки нет - она есть. > собственно, recv в некоторых случаях может выдавать 0 и это не всегда > ошибка (у нас CentOS 7, возможно, там какая-то своя магия еще, с > какими-нибудь сетевыми штуками бекпортированными в ядро 3.10) > > man recv > ... > "The value 0 may also be returned if the requested number of bytes to > receive from a stream socket was 0." > > собственно, в этом месте меняем текст. и, чудо, после этого залогированные > "upstream prematurely closed connection" идеально кореллируют с реальными > обрывами. > > вопрос - в этом месте действительно стоит логировать ошибку с таким текстом > ? может поменять уровень на info (или debug), а текст сделать что-то типа > "zero bytes read from recv" ? Если recv() возвращает 0 байт - в предположении, что буфер был не нулевого размера - то это означает, что соединение закрыто "той стороной". Если это происходит в момент времени, не предусмотренный протоколом - то это ошибка, и она логгируется соответственно. -- Maxim Dounin http://mdounin.ru/ ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: ошибка "upstream prematurely closed connection" - обсудим ?
не мимо темы. мы просим из recv столько то данных, возвращается ноль. дальнейшую отладку попробую собрать пн, 14 окт. 2019 г. в 12:33, Evgeniy Berdnikov : > On Mon, Oct 14, 2019 at 11:59:44AM +0500, Илья Шипицин wrote: > >добавил отладку. > >в recv передается не ноль. из recv возвращается ноль. > > Значит процитированный фрагмент man recv и все домыслы вокруг него > (насчёт специфики реализации в каком-то центосе) оказались мимо темы. > > Теперь самое время разобраться в обстоятельствах, при которых recv() > возвращает ноль. Смотрите что высылает бэкенд, что прилетает по сети. > -- > Eugene Berdnikov > ___ > nginx-ru mailing list > nginx-ru@nginx.org > http://mailman.nginx.org/mailman/listinfo/nginx-ru ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: ошибка "upstream prematurely closed connection" - обсудим ?
On Mon, Oct 14, 2019 at 11:59:44AM +0500, Илья Шипицин wrote: >добавил отладку. >в recv передается не ноль. из recv возвращается ноль. Значит процитированный фрагмент man recv и все домыслы вокруг него (насчёт специфики реализации в каком-то центосе) оказались мимо темы. Теперь самое время разобраться в обстоятельствах, при которых recv() возвращает ноль. Смотрите что высылает бэкенд, что прилетает по сети. -- Eugene Berdnikov ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: ошибка "upstream prematurely closed connection" - обсудим ?
добавил отладку. в recv передается не ноль. из recv возвращается ноль. вс, 13 окт. 2019 г. в 20:44, Илья Шипицин : > > > вс, 13 окт. 2019 г. в 20:11, Evgeniy Berdnikov : > >> On Sun, Oct 13, 2019 at 02:18:30PM +0500, Илья Шипицин wrote: >> >в одном месте - не завершается: >> > >> http://hg.nginx.org/nginx/file/tip/src/http/ngx_http_upstream.c#l2369 >> >собственно, recv в некоторых случаях может выдавать 0 и это не всегда >> >ошибка (у нас CentOS 7, возможно, там какая-то своя магия еще, с >> >какими-нибудь сетевыми штуками бекпортированными в ядро 3.10) >> >man recv >> >... >> >"The value 0 may also be returned if the requested number of bytes to >> >receive from a stream socket was 0." >> >> Насколько я разбираюсь в английском, "requested number of bytes" -- это >> значение аргумента len, т.е. ситуация, когда в recv() передают длину >> буфера равную нулю, т.е. из сокета запрашивается чтение нуля байт. >> Nginx действительно так делает? >> > > я не добавлял в это место логирование. не могу наверняка сказать. > у нас выключена настройка "proxy_buffering off;" и еще в каких-то моментах > конфиг отличается от дефолтного. > > возможно, что при некоторой комбинации параметров может передаваться 0 в > recv (я попробую в это место отладку добавить), > возможно, что 0 возращается по каким-то другим причинам, связанным с > особенностью recv под centos > > > >> >собственно, в этом месте меняем текст. и, чудо, после этого >> залогированные >> >"upstream prematurely closed connection" идеально кореллируют с >> реальными >> >обрывами. >> >> Что на что меняем? diff покажите. >> > > вроде бы это не должно иметь значения. > у меня три места, где генерируется "upstream prematurely closed > connection". одно из этих мест я меняю на что-то отличное, чтобы в логе > понять, > где срабатывает ошибка. допустим, меняю на "xyz" > > >> -- >> Eugene Berdnikov >> ___ >> nginx-ru mailing list >> nginx-ru@nginx.org >> http://mailman.nginx.org/mailman/listinfo/nginx-ru > > ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: ошибка "upstream prematurely closed connection" - обсудим ?
вс, 13 окт. 2019 г. в 20:11, Evgeniy Berdnikov : > On Sun, Oct 13, 2019 at 02:18:30PM +0500, Илья Шипицин wrote: > >в одном месте - не завершается: > >http://hg.nginx.org/nginx/file/tip/src/http/ngx_http_upstream.c#l2369 > >собственно, recv в некоторых случаях может выдавать 0 и это не всегда > >ошибка (у нас CentOS 7, возможно, там какая-то своя магия еще, с > >какими-нибудь сетевыми штуками бекпортированными в ядро 3.10) > >man recv > >... > >"The value 0 may also be returned if the requested number of bytes to > >receive from a stream socket was 0." > > Насколько я разбираюсь в английском, "requested number of bytes" -- это > значение аргумента len, т.е. ситуация, когда в recv() передают длину > буфера равную нулю, т.е. из сокета запрашивается чтение нуля байт. > Nginx действительно так делает? > я не добавлял в это место логирование. не могу наверняка сказать. у нас выключена настройка "proxy_buffering off;" и еще в каких-то моментах конфиг отличается от дефолтного. возможно, что при некоторой комбинации параметров может передаваться 0 в recv (я попробую в это место отладку добавить), возможно, что 0 возращается по каким-то другим причинам, связанным с особенностью recv под centos > >собственно, в этом месте меняем текст. и, чудо, после этого > залогированные > >"upstream prematurely closed connection" идеально кореллируют с > реальными > >обрывами. > > Что на что меняем? diff покажите. > вроде бы это не должно иметь значения. у меня три места, где генерируется "upstream prematurely closed connection". одно из этих мест я меняю на что-то отличное, чтобы в логе понять, где срабатывает ошибка. допустим, меняю на "xyz" > -- > Eugene Berdnikov > ___ > nginx-ru mailing list > nginx-ru@nginx.org > http://mailman.nginx.org/mailman/listinfo/nginx-ru ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: ошибка "upstream prematurely closed connection" - обсудим ?
On Sun, Oct 13, 2019 at 02:18:30PM +0500, Илья Шипицин wrote: >в одном месте - не завершается: >http://hg.nginx.org/nginx/file/tip/src/http/ngx_http_upstream.c#l2369 >собственно, recv в некоторых случаях может выдавать 0 и это не всегда >ошибка (у нас CentOS 7, возможно, там какая-то своя магия еще, с >какими-нибудь сетевыми штуками бекпортированными в ядро 3.10) >man recv >... >"The value 0 may also be returned if the requested number of bytes to >receive from a stream socket was 0." Насколько я разбираюсь в английском, "requested number of bytes" -- это значение аргумента len, т.е. ситуация, когда в recv() передают длину буфера равную нулю, т.е. из сокета запрашивается чтение нуля байт. Nginx действительно так делает? >собственно, в этом месте меняем текст. и, чудо, после этого залогированные >"upstream prematurely closed connection" идеально кореллируют с реальными >обрывами. Что на что меняем? diff покажите. -- Eugene Berdnikov ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
ошибка "upstream prematurely closed connection" - обсудим ?
привет, предыстория. видим ошибку в логах. вспоминаем концепцию, что с уровнем error логируются ошибки на стороне сервера. считаем, что ошибка действительно была. идем к клиенту - у клиента статус 200, ему хорошо, все, что он хотел считать, он вычитал. повторяем несколько раз, в большинстве случаев ситуация повторяется, в логах ошибка, у клиента все хорошо. ок. идем смотреть исходники вывод сообщения об ошибке встречается три раза ./nginx-1.17.4/src/http/ngx_http_upstream.c: "upstream prematurely closed connection"); ./nginx-1.17.4/src/http/ngx_http_upstream.c: "upstream prematurely closed connection"); ./nginx-1.17.4/src/http/ngx_http_upstream.c: "upstream prematurely closed connection"); в двух случаях запрос завершается статусом 502 ngx_http_upstream_finalize_request(r, u, NGX_HTTP_BAD_GATEWAY); в одном месте - не завершается: http://hg.nginx.org/nginx/file/tip/src/http/ngx_http_upstream.c#l2369 собственно, recv в некоторых случаях может выдавать 0 и это не всегда ошибка (у нас CentOS 7, возможно, там какая-то своя магия еще, с какими-нибудь сетевыми штуками бекпортированными в ядро 3.10) man recv ... "The value 0 may also be returned if the requested number of bytes to receive from a stream socket was 0." собственно, в этом месте меняем текст. и, чудо, после этого залогированные "upstream prematurely closed connection" идеально кореллируют с реальными обрывами. вопрос - в этом месте действительно стоит логировать ошибку с таким текстом ? может поменять уровень на info (или debug), а текст сделать что-то типа "zero bytes read from recv" ? Илья Шипицин ___ nginx-ru mailing list nginx-ru@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-ru
