Upstream prematurely closed connection while reading response header from upstream

Recently I tried to implemented an Nginx extension module to save the
request body to redis list (via RPUSH command) directly .

However, I got a 502 Bad Gateway error!

The error occurs after calling ngx_http_redis_create_request, before
ngx_http_redis_process_header() called [ nginx/logs/error.log ]

Anyone know what is the problem?

Here are the related log in [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”

===============================================================================

The configuration in Nginx as following shown

redis_pass 127.0.0.1:6379;
redis_db 3;
redis_key candice;

===============================================================================

Here are the source code of the module.

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;

}

===============================================================================

/* callbacks - To send command “SELECT \r\nRPUSH \r\n” to redis */
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;

}

Posted at Nginx Forum: