header already sent

[Dk Jack]

Hi,
I thought I solved my issue but it looks like I haven't. It just took some
time for the log messages to show up.
I've attached my code below. In my  code, the call HttpModuleProcessRequest
returns a non-zero value if
the requests needs to be blocked. Would appreciate if some one can help.
Thanks

-----------------------------------------------------------------------------------------------------------------------------------------------
PS: The issue seems to happen for request that my module blocked, so it
seems to be related to the send header call.

SendResponseBuffer(ngx_http_request_t *r, ngx_uint_t http_status, char
*reason, ngx_int_t rlen)
{
  ngx_int_t rc;
  ngx_log_t *log = r->connection->log;
  ngx_buf_t *buf = ngx_create_temp_buf(r->pool, (rlen+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;
  }

  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;

  r->headers_out.status = http_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";
  r->header_only = 1;
  r->headers_out.content_length_n = 0;

  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;
  }

  return ngx_http_output_filter(r, out_chain);
}

typedef struct {
  unsigned done:1;
} ngx_http_mod_ctx_t;

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_log_error(NGX_LOG_DEBUG, r->connection->log, 0,
                "%s: uri:\"%V\" uuri: \"%V\" call-count:%ud",
                __FUNCTION__, &r->uri, &r->unparsed_uri, r->main->count);

  ngx_int_t rc = 0;
  if (!ctx->done) {
    char buf[512];
    ngx_uint_t len;
    ngx_uint_t http_status;

    rc = HttpModuleProcessRequest(r, &http_status, buf, &len);
    if (!rc) {
      rc = SendResponseBuffer(r, http_status, buf, len);
    }
  }

  ctx->done = 1;
  //ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
  //              "%s: rc = %d, uri:\"%V\"", __FUNCTION__, rc, &r->uri);

  if ((rc != 0) && (rc != NGX_DECLINED)) {
    return rc;
  }

  // per http://www.nginxguts.com/2011/01/phases/, ACCESS_PHASE handler
should return NGX_OK here.
  // however, returning NGX_OK causes nginx to hang.
  return NGX_DECLINED;
}

static ngx_int_t
ngx_http_module_init (ngx_conf_t *cf)
{
  ngx_http_handler_pt       *hptr;
  ngx_http_core_main_conf_t *cmcf;

  cmcf = ngx_http_conf_get_module_main_conf(cf, ngx_http_core_module);
  hptr = ngx_array_push(&cmcf->phases[NGX_HTTP_ACCESS_PHASE].handlers);

  if (hptr == NULL) {
    ngx_log_error(NGX_LOG_ERR, cf->log, 0, "Cannot retrieve Nginx access
phase handler pointer");
    return NGX_ERROR;
  }

  *hptr = ngx_http_request_handler;
  ngx_log_error(NGX_LOG_INFO, cf->log, 0, "[init] Installed request
handler");

  return NGX_OK;
}


On Thu, Jul 5, 2018 at 5:44 PM Dk Jack <dnj0496 at gmail.com> wrote:

> Hi,
> I have an nginx module. The purpose of my module is to inspect every
> request and make a binary decision (i.e drop or allow). When dropping, I am
> sending a custom status code and response message. I've setup my module
> handler to be called in the NGX_HTTP_REWRITE_PHASE. Things seem to be
> working fine for the most part except for a small issue.
>
> I am seeing 'header already sent' messages in the nginx error.log. In my
> handler, I create a context for my module and attach it request using
> the ngx_http_set_ctx call. I am using the context to store some info and
> also to prevent my module from processing the same request multiple times.
> My module processes the request only once.
>
> I get the 'header already sent' message only for a fraction of the
> requests. The messages seem to be generated only for requests that I
> allowed in my module. In my module handler, I return an NGX_DECLINED return
> code when I allow a request. The message is not generated for every allowed
> request but only for some of the allowed requests. When the error is
> generated it is always for POST request and not all POST requests cause
> this error message to be logged.
>
> Could someone explain what could be going on here or where I should look
> at next to debug this further? Any pointers are appreciated. Thanks.
>
> Dk.
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20180706/d34d494d/attachment.html>