Error: 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 log within 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;

I pasted some related source code here

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 To send command "SELECT \r\nRPUSH \r\n" to 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; }

-------------Problems Reply------------

Now I have fixed the issue: upstream module failed to get response.

The related source code as following shown, [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;
}

There are various of conditions could lead to such result;

Client side

  • The buffer_size argument of recv() is set to 0, that is do not specify the buffer size. This is why this module failed, Fix issue by setting the buffer size to a non-zero value :-)

Server side

  • The backend server prematurely close the connection due to some reasons
Category:nginx Views:4 Time:2018-02-19
Tags: nginx

Related post

Copyright (C) dskims.com, All Rights Reserved.

processed in 0.104 (s). 11 q(s)