错误：上游过早关闭连接，同时从上游读取响应标头答案

【问题标题】：Error: upstream prematurely closed connection while reading response header from upstream错误：上游过早关闭连接，同时从上游读取响应标头
【发布时间】：2015-04-20 06:43:32
【问题描述】：

最近我尝试实现一个 Nginx 扩展模块，将请求正文直接保存到 redis 列表（通过 RPUSH 命令）。

但是，我收到了 502 Bad Gateway 错误！

在调用ngx_http_redis_create_request之后发生错误，在ngx_http_redis_process_header()之前调用[ nginx/logs/error.log ]

有人知道是什么问题吗？

这是 nginx/logs/error.log

中的日志

2015/04/20 13:56:54 [debug] 5759#0: *1 http process request line
2015/04/20 13:56:54 [debug] 5759#0: *1 http request line: "GET /test HTTP/1.1"
2015/04/20 13:56:54 [debug] 5759#0: *1 http uri: "/test"
2015/04/20 13:56:54 [debug] 5759#0: *1 http args: ""
2015/04/20 13:56:54 [debug] 5759#0: *1 http exten: ""
2015/04/20 13:56:54 [debug] 5759#0: *1 http process request header line
2015/04/20 13:56:54 [debug] 5759#0: *1 http header: "User-Agent: Wget/1.15 (linux-gnu)"
2015/04/20 13:56:54 [debug] 5759#0: *1 http header: "Accept: */*"
2015/04/20 13:56:54 [debug] 5759#0: *1 http header: "Host: localhost:8989"
2015/04/20 13:56:54 [debug] 5759#0: *1 http header: "Connection: Keep-Alive"
2015/04/20 13:56:54 [debug] 5759#0: *1 http header done
2015/04/20 13:56:54 [debug] 5759#0: *1 event timer del: 3: 1429509474481
2015/04/20 13:56:54 [debug] 5759#0: *1 test location: "/"
2015/04/20 13:56:54 [debug] 5759#0: *1 test location: "general/test"
2015/04/20 13:56:54 [debug] 5759#0: *1 test location: "test"
2015/04/20 13:56:54 [debug] 5759#0: *1 using configuration "/test"
2015/04/20 13:56:54 [debug] 5759#0: *1 http cl:-1 max:1048576
2015/04/20 13:56:54 [debug] 5759#0: *1 generic phase: 1
2015/04/20 13:56:54 [debug] 5759#0: *1 generic phase: 2
2015/04/20 13:56:54 [debug] 5759#0: *1 access phase: 3
2015/04/20 13:56:54 [debug] 5759#0: *1 access phase: 4
2015/04/20 13:56:54 [debug] 5759#0: *1 post access phase: 5
2015/04/20 13:56:54 [debug] 5759#0: *1 posix_memalign: 00000000012627D0:4096 @16
2015/04/20 13:56:54 [debug] 5759#0: *1 http init upstream, client timer: 0
2015/04/20 13:56:54 [debug] 5759#0: *1 epoll add event: fd:3 op:3 ev:80002005
2015/04/20 13:56:54 [debug] 5759#0: *1 http cleanup add: 0000000001262788
2015/04/20 13:56:54 [debug] 5759#0: *1 get rr peer, try: 1
2015/04/20 13:56:54 [debug] 5759#0: *1 socket 9
2015/04/20 13:56:54 [debug] 5759#0: *1 epoll add connection: fd:9 ev:80002005
2015/04/20 13:56:54 [debug] 5759#0: *1 connect to 127.0.0.1:6379, fd:9 #2
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream connect: -2
2015/04/20 13:56:54 [debug] 5759#0: *1 posix_memalign: 000000000125B640:128 @16
2015/04/20 13:56:54 [debug] 5759#0: *1 event timer add: 9: 60000:1429509474482
2015/04/20 13:56:54 [debug] 5759#0: *1 http finalize request: -4, "/test?" a:1, c:2
2015/04/20 13:56:54 [debug] 5759#0: *1 http request count:2 blk:0
2015/04/20 13:56:54 [debug] 5759#0: timer delta: 1
2015/04/20 13:56:54 [debug] 5759#0: posted events 0000000000000000
2015/04/20 13:56:54 [debug] 5759#0: worker cycle
2015/04/20 13:56:54 [debug] 5759#0: epoll timer: 60000
2015/04/20 13:56:54 [debug] 5759#0: epoll: fd:3 ev:0004 d:00007F39455B51B0
2015/04/20 13:56:54 [debug] 5759#0: *1 http run request: "/test?"
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream check client, write event:1, "/test"
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream recv(): -1 (11: Resource temporarily unavailable)
2015/04/20 13:56:54 [debug] 5759#0: epoll: fd:9 ev:0004 d:00007F39455B5280
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream request: "/test?"
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream send request handler
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream send request
2015/04/20 13:56:54 [debug] 5759#0: *1 chain writer buf fl:0 s:30
2015/04/20 13:56:54 [debug] 5759#0: *1 chain writer in: 0000000001262B88
2015/04/20 13:56:54 [debug] 5759#0: *1 writev: 30
2015/04/20 13:56:54 [debug] 5759#0: *1 chain writer out: 0000000000000000
2015/04/20 13:56:54 [debug] 5759#0: *1 event timer del: 9: 1429509474482
2015/04/20 13:56:54 [debug] 5759#0: *1 event timer add: 9: 60000:1429509474482
2015/04/20 13:56:54 [debug] 5759#0: timer delta: 0
2015/04/20 13:56:54 [debug] 5759#0: posted events 0000000000000000
2015/04/20 13:56:54 [debug] 5759#0: worker cycle
2015/04/20 13:56:54 [debug] 5759#0: epoll timer: 60000
2015/04/20 13:56:54 [debug] 5759#0: epoll: fd:9 ev:0005 d:00007F39455B5280
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream request: "/test?"
2015/04/20 13:56:54 [debug] 5759#0: *1 http upstream process header
2015/04/20 13:56:54 [debug] 5759#0: *1 recv: fd:9 0 of 0
2015/04/20 13:56:54 [error] 5759#0: *1 upstream prematurely closed connection while reading response header from upstream, client: 127.0.0.1, server: localhost,request: "GET /test HTTP/1.1", upstream: "redis://127.0.0.1:6379", host: "localhost:8989"

Nginx中的配置如下图

redis_pass 127.0.0.1:6379;

redis_db 3;

redis_key candice;

我这里贴了一些相关的源码

static ngx_command_t ngx_http_redis_commands[] = {
    {
        ngx_string("redis_pass"),
        NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1,
        ngx_http_redis_pass,
        NGX_HTTP_LOC_CONF_OFFSET,
        0,
        NULL
    },
    {
        ngx_string("redis_db"),
        NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1,
        ngx_conf_set_num_slot,
        NGX_HTTP_LOC_CONF_OFFSET,
        offsetof(ngx_http_redis_loc_conf_t, db),
        NULL
    },
    {   
        ngx_string("redis_key"),
        NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1,
        ngx_conf_set_str_slot,
        NGX_HTTP_LOC_CONF_OFFSET,
        offsetof(ngx_http_redis_loc_conf_t, key),
        NULL
    },
    {
        ngx_string("redis_connect_timeout"),
        NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1,
        ngx_conf_set_msec_slot,
        NGX_HTTP_LOC_CONF_OFFSET,
        offsetof(ngx_http_redis_loc_conf_t, upstream.connect_timeout),
        NULL
    },
    {
        ngx_string("redis_send_timeout"),
        NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1,
        ngx_conf_set_msec_slot,
        NGX_HTTP_LOC_CONF_OFFSET,
        offsetof(ngx_http_redis_loc_conf_t, upstream.send_timeout),
        NULL
    },
    {
        ngx_string("redis_read_timeout"),
        NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1,
        ngx_conf_set_msec_slot,
        NGX_HTTP_LOC_CONF_OFFSET,
        offsetof(ngx_http_redis_loc_conf_t, upstream.read_timeout),
        NULL
    },
    ngx_null_command,
};

ngx_http_redis_handler

static ngx_int_t
ngx_http_redis_handler(ngx_http_request_t *r)
{
    ngx_http_redis_loc_conf_t *rlcf;
    ngx_http_upstream_t *u;
    ngx_int_t rc;

    /* set up upstream structure */
    if (ngx_http_upstream_create(r) != NGX_OK)
    {
        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0, "ngx_http_upstream_create() failed");
        return NGX_HTTP_INTERNAL_SERVER_ERROR;
    }

    u = r->upstream;
    ngx_str_set(&u->schema, "redis://");

    rlcf = ngx_http_get_module_loc_conf(r, ngx_http_redis_module);
    u->conf = &rlcf->upstream;
    
    /* attach the callback functions */
    u->create_request = ngx_http_redis_create_request;
    u->reinit_request = ngx_http_redis_reinit_request;
    u->process_header = ngx_http_redis_process_header;
    u->finalize_request = ngx_http_redis_finalize_request;

    rc = ngx_http_read_client_request_body(r, ngx_http_upstream_init);
    if (rc > NGX_HTTP_SPECIAL_RESPONSE)
        return rc;
    return NGX_DONE;
}

ngx_http_redis_create_request 发送命令 "SELECT \r\nRPUSH \r\n" 到 redis

/* callbacks */
static ngx_int_t ngx_http_redis_create_request(ngx_http_request_t *r)
{
    ngx_http_redis_loc_conf_t * rlcf;
    ngx_chain_t *cl, *body;
    ngx_buf_t *buf, *b;

    /* Do not forget to change the following offset when modifying the query string */
    ngx_str_t query = ngx_string("SELECT %ui\r\nRPUSH %V ");
    size_t len = query.len - 5;

    rlcf = ngx_http_get_module_loc_conf(r, ngx_http_redis_module);
    len += (rlcf->db > 9 ? 2 : 1) + rlcf->key.len;

    /* Create temporary buffer for request with size len. */
    buf = ngx_create_temp_buf(r->pool, len);
    if (buf == NULL) {
        return NGX_ERROR;
    }
    ngx_snprintf(buf->pos, len, (char*)query.data, rlcf->db, &rlcf->key);
    buf->last = buf->pos + len;

    cl = ngx_alloc_chain_link(r->pool);
    if (cl == NULL) {
        return NGX_ERROR;
    }

    cl->buf = buf;
    cl->next = NULL;

    body = r->upstream->request_bufs;
    r->upstream->request_bufs = cl;
    while (body)
    {
        b = ngx_alloc_buf(r->pool);
        if (b == NULL)
            return NGX_ERROR;

        ngx_memcpy(b, body->buf, sizeof(ngx_buf_t));
        cl->next = ngx_alloc_chain_link(r->pool);
        if (cl->next == NULL)
            return NGX_ERROR;

        cl = cl->next;
        cl->buf = b;
        body = body->next;
    }
    *cl->buf->last++ = CR; *cl->buf->last++ = LF;
    cl->next = NULL;
    return NGX_OK;
}

【问题讨论】：

注意：ngx_http_redis_create_request()方法执行成功，可以看到redis中的数据。
模块的整个实现见ngx-redis3
你考虑过使用 ngx_lua 模块吗？它有一个 redis 异步库，你可以在 lua 中轻松实现你想要的。

标签： nginx

【解决方案1】：

现在我已经解决了这个问题：上游模块无法得到响应。

相关源码如下图，[Line 1899, File src/http/ngx_http_upstream.c]

n = c->recv(c, u->buffer.last, u->buffer.end - u->buffer.last);
if (n == NGX_AGAIN) {
    if (ngx_handle_read_event(c->read, 0) != NGX_OK) {
        ngx_http_upstream_finalize_request(r, u,
                                       NGX_HTTP_INTERNAL_SERVER_ERROR);
        return;
    }
    return;
}

if (n == 0) {
    ngx_log_error(NGX_LOG_ERR, c->log, 0,
                  "upstream prematurely closed connection");
}

if (n == NGX_ERROR || n == 0) {
    ngx_http_upstream_next(r, u, NGX_HTTP_UPSTREAM_FT_ERROR);
    return;
}

有多种情况会导致这样的结果；

客户端

recv() 的buffer_size 参数设置为0，即不指定缓冲区大小。这就是这个模块失败的原因，Fix issue by setting the buffer size to a non-zero value :-)

服务器端

后端服务器由于某些原因提前关闭连接

【讨论】：

【解决方案2】：

这是上游的一个明确问题，我使用了独角兽，而 sendmail 发送邮件时出现问题，最终超时。一旦我解决了这个问题，一切都很顺利。

【讨论】：