2: header already sent
Roman Arutyunyan
arut at nginx.com
Mon Jul 16 11:29:15 UTC 2018
Hi Dk Jack,
On Sun, Jul 15, 2018 at 06:09:24PM -0700, Dk Jack wrote:
> Hi Roman,
> Sorry, it took a while for me to test the debug build. Since my module was
> using timers, the debug logs in ngx_event_timer.{c,h} were causing a crash
> (see end of email for details about the crash). Anyways, the debug log
> attached at the end of the email.
>
> Looking at the debug logs, it looks like the ngx_http_finalize_request is
> calling ngx_http_special_response_handler for any 'rc >=
> NGX_HTTP_SPECIAL_RESPONSE (300)'. Since I was passing a 403 for the rc
> value, it was calling the special_response_handler function which in turn
> calls the send_header function. Since I had already called the send_header
> function before calling the finalize_request, it generates the 'header
> already sent' message.
Yes, you should either produce output by yourself by calling
ngx_http_send_header/ngx_http_output_filter, or finalize the request with
a code >= 300. In the latter case nginx will output a standard response for
this code. But you should never do both.
> After going over the ngx_http_finalize_request code, I realized, if I
> invoked the ngx_http_finalize_request function with 'rc = NGX_HTTP_CLOSE',
> the finalize_request function will terminate the request and will not call
> the ngx_http_special_response_handler which was causing the problem. I
> tried it and it seems to work. Not sure if this the correct approach.
Finalizing a request with NGX_HTTP_CLOSE is probably not a very good idea,
unless you are absolutely sure you want to close the client connection for some
reason. Normally you should finalize it with NGX_OK after you are done with
sending response header and body. A standard approach here is finalizing the
response with the result of ngx_http_output_filter().
Keep in mind that if you're doing all this in an access phase handler, the
response code from your handler may or may not be passed to
ngx_http_finalize_request(). See ngx_http_core_access_phase() function for
details.
> Please let me know.
>
> Thanks for your help. Greatly appreciate it.
> ./D
>
> ---------------------------------------------------------------------------------------------------------------
> event_timer crash when debug enabled:
> #define ngx_event_ident(p) ((ngx_connection_t *) (p))->fd
>
> ngx_log_debug2(NGX_LOG_DEBUG_EVENT, ev->log, 0,
> "event timer del: %d: %M",
> ngx_event_ident(ev->data), ev->timer.key);
>
> event_timer.{c,h} files have these sort of debug statements sprinkled all
> over these two files. The ngx_event_ident macro seems to treat the data
> pointer as a ngx_connection_t pointer and is attempting to dereference it
> which causes the crash. In my case, the ev->data was NULL.
Yes, event is supposed to always point to a connection object. However,
if you have a different object referenced by ev->data, just make sure it has
a properly sized value at offsetof(ngx_connection_t, fd). Having NULL in
ev->data is not allowed.
> -------------------------------------------------------------------------------------------------------------------
>
> 2018/07/15 23:28:58 [error] 12381#12381: *2 ngx_http_request_handler: rc =
> 403, uri:"/a/b/c", client: 10.3.28.146, server: live.testdomain.com,
> request: "GET /a/b/c HTTP/1.1", host: "live.testdomain.com"
> 2018/07/15 23:28:58 [error] 12381#12381: *2 ngx_http_request_handler:
> finalize_req rc = 403, uri:"/a/b/c", client: 10.3.28.146, server:
> live.testdomain.com, request: "GET /a/b/c HTTP/1.1", host: "
> live.testdomain.com"
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http finalize request: 403,
> "/a/b/c?" a:1, c:1
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http special response: 403,
> "/a/b/c?"
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http set discard body
> 2018/07/15 23:28:58 [alert] 12381#12381: *2 header already sent, client:
> 10.3.28.146, server: live.testdomain.com, request: "GET /a/b/c HTTP/1.1",
> host: "live.testdomain.com"
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http finalize request: -1,
> "/a/b/c?" a:1, c:1
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http terminate request count:1
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http terminate cleanup count:1
> blk:0
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http posted request: "/a/b/c?"
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http terminate handler count:1
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http request count:1 blk:0
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http close request
> 2018/07/15 23:28:58 [debug] 12381#12381: *2 http log handler
>
>
> On Sat, Jul 14, 2018 at 10:26 PM Roman Arutyunyan <arut at nginx.com> wrote:
>
> > Hi,
> >
> > On Sat, Jul 14, 2018 at 05:21:02PM -0700, Dk Jack wrote:
> > > Hi Roman,
> > > Thanks for taking the time to respond to my question.
> > >
> > > I've tried your suggestion. I've done a finalize_req and tried
> > > NGX_DONE/OK/... All give me the same result. I get the same result with
> > or
> > > without the finalize_req i.e. I still see the 'header already sent'
> > > message. I've experimented with the different 'rc' values for the
> > > finalize_req i.e. 'rc = NGX_DONE/OK/ERROR' as well. I still see the same
> > > result. Please let me know if you have any other suggestions you'd like
> > me
> > > to try. Thanks.
> >
> > Can you show your debug log?
> >
> > https://nginx.org/en/docs/debugging_log.html
> >
> > > On Sat, Jul 14, 2018 at 2:37 PM Roman Arutyunyan <arut at nginx.com> wrote:
> > >
> > > > Hi Dk Jack,
> > > >
> > > > On Fri, Jul 13, 2018 at 01:18:40PM -0700, Dk Jack wrote:
> > > > > Sorry, I made a typo in my earlier email. Please read the following
> > > > > sentence:
> > > > >
> > > > > "When I send the response in the *content* phase handler, I am am
> > seeing
> > > > > 'header already sent' messages in the error log."
> > > > >
> > > > > as
> > > > >
> > > > > "When I send the response in the *access* phase handler, I am am
> > seeing
> > > > > 'header already sent' messages in the error log."
> > > >
> > > > That's because you do not finalize the request after you send a
> > response in
> > > > the access handler. A content handler (standard static or another
> > one) is
> > > > still called at the content phase. It tries to send a second response
> > and
> > > > obviously gets this error.
> > > >
> > > > Finalize the request in the access phase after you send the response
> > with
> > > > this call:
> > > >
> > > > ngx_http_finalize_request(r, rc)
> > > >
> > > > where rc is what ngx_http_output_filter() returned. Then return
> > NGX_DONE
> > > > from the access handler to prevent further request processing.
> > > >
> > > > If you want to return a standard error page, simply return its HTTP
> > status
> > > > code
> > > > from your access handler instead.
> > > >
> > > > > On Thu, Jul 12, 2018 at 1:29 PM Dk Jack <dnj0496 at gmail.com> wrote:
> > > > >
> > > > > > Hi,
> > > > > > Sorry for sending this again. I haven't been able to resolve my
> > issue.
> > > > > > I've read several modules for example and gone over several docs
> > etc.
> > > > but
> > > > > > with no success so far.
> > > > > >
> > > > > > In my module, I need to either drop the request or allow the
> > request.
> > > > When
> > > > > > I drop the request, I need to send custom response and status. The
> > > > custom
> > > > > > response and status don't come from the config file. When I send
> > the
> > > > > > response in the content phase handler, I am am seeing 'header
> > already
> > > > sent'
> > > > > > messages in the error log. How can prevent further processing of
> > the
> > > > > > request after my handler is called for the terminal case?
> > > > > >
> > > > > > Since my module needs to examine all requests irrespective of the
> > uri,
> > > > I
> > > > > > tried registering a content phase handler and send the custom
> > response
> > > > in
> > > > > > that handler. However, my content phase handler is never invoked. I
> > > > suspect
> > > > > > some other content handler is overriding my content handler. Is
> > there
> > > > a
> > > > > > way I can prevent that i.e. for a request, can I force only my
> > content
> > > > > > handler to be called.
> > > > > >
> > > > > > Please let me know what I am doing wrong? I just need to
> > send/perform
> > > > > > custom response/actions when a request matches my criteria. I've
> > > > include a
> > > > > > skeleton of my code.
> > > > > > Any inputs are greatly appreciated. Thanks.
> > > > > >
> > > > > > regards,
> > > > > > Dk.
> > > > > >
> > > > > > http_mod_send_response(ngx_http_request_t *r, ngx_uint_t
> > custom_status,
> > > > > > char *body, ngx_int_t blen)
> > > > > > {
> > > > > > ngx_int_t rc;
> > > > > > ngx_log_t *log = r->connection->log;
> > > > > > ngx_buf_t *buf = ngx_create_temp_buf(r->pool, (blen+16)); // pad.
> > > > > >
> > > > > > if (NULL == buf) {
> > > > > > ngx_log_error(NGX_LOG_ERR, log, 0, "%s: Failed to allocate
> > buffer",
> > > > > > __FUNCTION__);
> > > > > > return NGX_ERROR;
> > > > > > }
> > > > > >
> > > > > > buf->last = ngx_copy(buf->start, (unsigned char*) data, dlen);
> > > > > > rc = ngx_http_discard_request_body(r);
> > > > > > if (rc != NGX_OK) {
> > > > > > ngx_log_error(NGX_LOG_ERR, log, 0, "%s: Discard req. body
> > failed.
> > > > > > rc=%i", __FUNCTION__, rc);
> > > > > > return rc;
> > > > > > }
> > > > > >
> > > > > > r->headers_out.status = custom_status;
> > > > > > r->headers_out.content_length_n = buf->last - buf->pos;
> > > > > > r->headers_out.content_type.len = sizeof("text/plain") - 1;
> > > > > > r->headers_out.content_type.data = (u_char *) "text/plain";
> > > > > >
> > > > > > rc = ngx_http_send_header(r);
> > > > > > if (rc == NGX_ERROR || rc > NGX_OK || r->header_only) {
> > > > > > ngx_log_error(NGX_LOG_ERR, log, 0, "%s: Send header failed.
> > rc=%i",
> > > > > > __FUNCTION__, rc);
> > > > > > return rc;
> > > > > > }
> > > > > >
> > > > > > ngx_chain_t *out_chain = ngx_alloc_chain_link(r->pool);
> > > > > > if (NULL == out_chain) {
> > > > > > ngx_log_error(NGX_LOG_ERR, log, 0, "%s: Buffer chain alloc
> > failed",
> > > > > > __FUNCTION__);
> > > > > > return NGX_ERROR;
> > > > > > }
> > > > > >
> > > > > > out_chain->buf = buf;
> > > > > > out_chain->next = NULL;
> > > > > > buf->last_buf = 1;
> > > > > > buf->last_in_chain = 1;
> > > > > >
> > > > > > return ngx_http_output_filter(r, out_chain);
> > > > > > }
> > > > > >
> > > > > > typedef struct {
> > > > > > unsigned done:1;
> > > > > > } ngx_http_mod_ctx_t;
> > > > > >
> > > > > > int
> > > > > > http_module_process_request(ngx_http_request_t *r, ngx_uint_t
> > *status,
> > > > > > char *body, ngx_uint_t *blen)
> > > > > > {
> > > > > > if (/* request matches criteria */) {
> > > > > > /* other boiler plate code */
> > > > > > *status = get_custom_status();
> > > > > > *body = get_custom_body();
> > > > > > *blen = ngx_strlen(body);
> > > > > > return *status; // this can be different from custom status.
> > > > > > }
> > > > > >
> > > > > > return NGX_DECLINED;
> > > > > > }
> > > > > >
> > > > > > static ngx_int_t
> > > > > > ngx_http_request_handler(ngx_http_request_t *r)
> > > > > > {
> > > > > > ngx_http_mod_ctx_t *ctx = ngx_http_get_module_ctx(r,
> > > > nginx_http_module);
> > > > > >
> > > > > > if (ctx) {
> > > > > > ngx_log_error(NGX_LOG_DEBUG, r->connection->log, 0, "duplicate
> > > > > > invokation");
> > > > > > return NGX_DECLINED;
> > > > > > } else {
> > > > > > ctx = ngx_palloc(r->connection->pool,
> > sizeof(ngx_http_mod_ctx_t));
> > > > > > if (ctx == NULL) {
> > > > > > ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
> > > > > > "Out of memory. Cannot allocate context");
> > > > > > return NGX_ERROR;
> > > > > > }
> > > > > >
> > > > > > ctx->done = 0;
> > > > > > ngx_http_set_ctx(r, ctx, nginx_http_module);
> > > > > > }
> > > > > >
> > > > > > ngx_int_t rc = 0;
> > > > > > char custom_body[512];
> > > > > > ngx_uint_t blen;
> > > > > > ngx_uint_t custom_status;
> > > > > > if (!ctx->done) {
> > > > > > rc = http_module_process_request(r, &custom_status,
> > custom_body,
> > > > > > &blen);
> > > > > > }
> > > > > >
> > > > > > ctx->done = 1;
> > > > > > if ((rc != 0) && (rc != NGX_DECLINED)) {
> > > > > > return http_mod_send_response(r, custom_status, custom_body,
> > blen);
> > > > > > /* alternate implementation, send response in content handler.
> > > > > > ngx_buf_t *buf = ngx_create_temp_buf(r->pool, blen);
> > > > > > buf->last = ngx_copy(buf->start, (unsigned char*) data,
> > dlen);
> > > > > > ctx->custom_body = buf;
> > > > > > ctx->rcode = custom_status;
> > > > > > */
> > > > > > }
> > > > > >
> > > > > > return NGX_DECLINED;
> > > > > > }
> > > > > >
> > > > > > static ngx_int_t
> > > > > > http_module_content_handler(ngx_http_request_t *r)
> > > > > > {
> > > > > > ngx_log_error(NGX_LOG_ERR, r->connection->log, 0, "%s: invoked",
> > > > > > __FUNCTION__);
> > > > > > ngx_http_ss_ctx_t *ctx = ngx_http_get_module_ctx(r,
> > > > > > nginx_mitigator_module);
> > > > > >
> > > > > > if (ctx && ctx->content) {
> > > > > > ctx->content = 0;
> > > > > > return http_mod_send_response(r, ctx->rcode, ctx->custom_body);
> > > > > > } else {
> > > > > > ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
> > > > > > "%s: ctx = %p, content = %d", __FUNCTION__, ctx,
> > ctx
> > > > ?
> > > > > > ctx->content : -1);
> > > > > > }
> > > > > >
> > > > > > return NGX_DECLINED;
> > > > > > }
> > > > > >
> > > > > > static ngx_int_t
> > > > > > ngx_http_module_init (ngx_conf_t *cf)
> > > > > > {
> > > > > > ngx_http_core_main_conf_t *cmcf =
> > > > ngx_http_conf_get_module_main_conf(cf,
> > > > > > ngx_http_core_module);
> > > > > >
> > > > > > if (!cmcf) {
> > > > > > ngx_log_error(NGX_LOG_ERR, cf->log, 0, "Failed to retrieve
> > module
> > > > main
> > > > > > conf");
> > > > > > return NGX_ERROR;
> > > > > > }
> > > > > >
> > > > > > ngx_http_handler_pt *hptr =
> > > > > > ngx_array_push(&cmcf->phases[NGX_HTTP_ACCESS_PHASE].handlers);
> > > > > > if (hptr == NULL) {
> > > > > > ngx_log_error(NGX_LOG_ERR, cf->log, 0, "Could not retrieve
> > access
> > > > > > phase handler");
> > > > > > return NGX_ERROR;
> > > > > > }
> > > > > >
> > > > > > *hptr = ngx_http_request_handler;
> > > > > > ngx_log_error(NGX_LOG_INFO, cf->log, 0, "[init] Installed request
> > > > > > handler");
> > > > > >
> > > > > > ngx_http_handler_pt *cptr =
> > > > > > ngx_array_push(&cmcf->phases[NGX_HTTP_CONTENT_PHASE].handlers);
> > > > > > if (cptr == NULL) {
> > > > > > ngx_log_error(NGX_LOG_ERR, cf->log, 0, "Could not retrieve
> > access
> > > > > > phase handler");
> > > > > > return NGX_ERROR;
> > > > > > }
> > > > > >
> > > > > > *cptr = ngx_http_request_handler;
> > > > > > ngx_log_error(NGX_LOG_INFO, cf->log, 0, "[init] Installed request
> > > > > > handler");
> > > > > >
> > > > > > return NGX_OK;
> > > > > > }
> > > > > >
> > > > > >
> > > > > >
> > > >
> > > > > _______________________________________________
> > > > > nginx-devel mailing list
> > > > > nginx-devel at nginx.org
> > > > > http://mailman.nginx.org/mailman/listinfo/nginx-devel
> > > >
> > > >
> > > > --
> > > > Roman Arutyunyan
> > > > _______________________________________________
> > > > nginx-devel mailing list
> > > > nginx-devel at nginx.org
> > > > http://mailman.nginx.org/mailman/listinfo/nginx-devel
> > > >
> >
> > > _______________________________________________
> > > nginx-devel mailing list
> > > nginx-devel at nginx.org
> > > http://mailman.nginx.org/mailman/listinfo/nginx-devel
> >
> >
> > --
> > Roman Arutyunyan
> > _______________________________________________
> > nginx-devel mailing list
> > nginx-devel at nginx.org
> > http://mailman.nginx.org/mailman/listinfo/nginx-devel
> >
> _______________________________________________
> nginx-devel mailing list
> nginx-devel at nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-devel
--
Roman Arutyunyan
More information about the nginx-devel
mailing list