worker process exited on signal 11 (core dumped)
Maxim Dounin
mdounin на mdounin.ru
Пт Фев 19 22:40:57 MSK 2010
Hello!
On Fri, Feb 19, 2010 at 07:41:07PM +0300, Igor Sysoev wrote:
> On Tue, Feb 16, 2010 at 02:54:29PM +0300, Maxim Dounin wrote:
>
> > Hello!
> >
> > On Wed, Feb 10, 2010 at 09:42:47PM +0300, Vladimir Sopot wrote:
> >
> > >
> > > On Feb 10, 2010, at 3:49 PM, Maxim Dounin wrote:
> > >
> > > >>> Ok, кажется я понял проблему. Судя по всему memcached_pass не
> > > >>> дожидается полного прилёта trailer'а ("END") и ругается. А в
> > > >>> случае keepalive остатки trailer'а долетают в ответ на следующий
> > > >>> запрос.
> > > >>>
> > > >>> По идее строка "invalid trailer" должна наблюдаться и без
> > > >>> keepalive (но скорее всего реже), а "invalid response" - только
> > > >>> если keepalive включён.
> > > >>
> > > >> 50 минут - полет нормальный,
> > > >>
> > > >> # grep -c 'subrequests cycle while processing' error.log
> > > >> 22076
> > > >> # grep memcached error.log
> > > >> #
> > > >
> > > > Видимо "реже" в данном случае вырождается в "почти никогда".
> > >
> > > Однако, все же "почти" никогда:
> > >
> > > # sed -n "1 p" error.log
> > > 2010/02/10 16:08:53 [error] 14875#0: *282680 directory index of "/wwwroot/" is forbidden
> > > # grep memcached error.log
> > > 2010/02/10 19:13:00 [error] 7643#0: *9676423 memcached sent invalid trailer while sending to client
> > > 2010/02/10 19:40:46 [error] 7638#0: *11190967 memcached sent invalid trailer while sending to client
> > > 2010/02/10 19:44:17 [error] 7641#0: *11386082 memcached sent invalid trailer while sending to client
> > > 2010/02/10 19:50:40 [error] 7646#0: *11737608 memcached sent invalid trailer while sending to client
> > > 2010/02/10 20:31:27 [error] 14006#0: *13901259 memcached sent invalid trailer while sending to client
> > > 2010/02/10 21:28:42 [error] 20249#0: *16943253 memcached sent invalid trailer while sending to client
> >
> > Патч.
> >
> > Maxim Dounin
>
> > # HG changeset patch
> > # User Maxim Dounin <mdounin at mdounin.ru>
> > # Date 1266320928 -10800
> > # Node ID 9009f1982e02d6f0614d4ddeae0672042442775a
> > # Parent 09972a4975970f7c3510177b8a287283d3a53c58
> > Memcached: correctly handle trailer split into several packets.
> >
> > With old code message "[error] ... memcached sent invalid trailer" may appear
> > in logs for no reason. It doesn't cause any harm except message itself
> > with official nginx though may cause spurious errors on connection reuse with
> > upstream keepalive module.
> >
> > diff --git a/src/http/modules/ngx_http_memcached_module.c b/src/http/modules/ngx_http_memcached_module.c
> > --- a/src/http/modules/ngx_http_memcached_module.c
> > +++ b/src/http/modules/ngx_http_memcached_module.c
> > @@ -432,15 +432,20 @@ ngx_http_memcached_filter(void *data, ss
> >
> > if (ngx_strncmp(b->last,
> > ngx_http_memcached_end + NGX_HTTP_MEMCACHED_END - ctx->rest,
> > - ctx->rest)
> > + bytes)
> > != 0)
> > {
> > ngx_log_error(NGX_LOG_ERR, ctx->request->connection->log, 0,
> > "memcached sent invalid trailer");
> > +
> > + u->length = 0;
> > + ctx->rest = 0;
> > +
> > + return NGX_OK;
> > }
> >
> > - u->length = 0;
> > - ctx->rest = 0;
> > + u->length -= bytes;
> > + ctx->rest -= bytes;
> >
> > return NGX_OK;
> > }
>
> Макс, до 0.6.14 был практический такой же код, который ты привёл.
> Commit message: "fix memcached END test"
Угу, вижу:
*) Bugfix: a worker process may got caught in an endless loop, if the
memcached was used.
К сожалению этой проблемой занимался не я, и тестов я так понимаю
на неё нет... ;) Ниже разбор по коду что это было.
> Index: src/http/modules/ngx_http_memcached_module.c
> ===================================================================
> --- src/http/modules/ngx_http_memcached_module.c (revision 873)
> +++ src/http/modules/ngx_http_memcached_module.c (revision 874)
> @@ -426,15 +426,15 @@
>
> if (ngx_strncmp(b->last,
> ngx_http_memcached_end + NGX_HTTP_MEMCACHED_END - ctx->rest,
> - bytes)
> + ctx->rest)
> != 0)
> {
> ngx_log_error(NGX_LOG_ERR, ctx->request->connection->log, 0,
> "memcached sent invalid trailer");
> }
>
> - u->length -= bytes;
> - ctx->rest -= bytes;
> + u->length = 0;
> + ctx->rest = 0;
Вот тут - не было выхода по ошибке вообще, а стал безусловный
выход в том числе из-за недочитанности ответа.
>
> return NGX_OK;
> }
> @@ -453,7 +453,8 @@
>
> *ll = cl;
>
> - cl->buf->pos = b->last;
> + last = b->last;
> + cl->buf->pos = last;
> b->last += bytes;
> cl->buf->last = b->last;
>
> @@ -461,20 +462,19 @@
> "memcached filter bytes:%z size:%z length:%z rest:%z",
> bytes, b->last - b->pos, u->length, ctx->rest);
>
> - if (b->last - b->pos <= (ssize_t) (u->length - NGX_HTTP_MEMCACHED_END)) {
> + if (bytes <= (ssize_t) (u->length - NGX_HTTP_MEMCACHED_END)) {
В старом коде проверялось "b->last - b->pos" - т.е. сколько лежит
в буфере. В новом проверяется bytes - т.е. сколько байт принято в
этом вызове фильтра.
Поскольку u->length имеет смысл только для этого вызова фильтра -
проверять надо bytes (i.e. в новом коде правильно). В старом коде
прочитанная половина ответа могла привести к решению "мы уже всё
прочитали, надо парсить END".
> u->length -= bytes;
> return NGX_OK;
> }
>
> + last += u->length - NGX_HTTP_MEMCACHED_END;
>
> - last = b->pos + u->length - NGX_HTTP_MEMCACHED_END;
> -
> if (ngx_strncmp(last, ngx_http_memcached_end, b->last - last) != 0) {
> ngx_log_error(NGX_LOG_ERR, ctx->request->connection->log, 0,
> "memcached sent invalid trailer");
> }
>
> - ctx->rest = u->length - (b->last - b->pos);
> + ctx->rest -= b->last - last;
А вот тут в старом коде дополнительный сюрприз: если в буфере уже
лежит больше чем u->length, то ctx->rest станет отрицательным. А
он size_t, т.е. станет он большим положительным.
> b->last = last;
> cl->buf->last = last;
> u->length = ctx->rest;
Ну и тут u->length ставится из большого отрицательного ctx->rest,
что приводит к вечноживущему соединению с memcached.
И при этом, как мы помним, выхода по ошибкам сравнения с END - не
предусмотрено.
Бесконечного цикла я тут всё равно не вижу, но IMHO и того что
видно - хватает за глаза. Намусорить в error log на больших
ответах оно могло прилично.
В тестах на 0.6.13 я ругань воспроизвести могу (при использовании
ssi include set="" и инструментированного бекенда). На 0.8.33 с
патчем та же проблема не воспроизводится (и не должна).
Тест вот тут:
http://mdounin.ru/hg/nginx-tests/rev/25047dc6ae9b
Maxim Dounin
Подробная информация о списке рассылки nginx-ru