Mercurial > hg > nginx
view src/core/ngx_log.c @ 9300:5be23505292b
SSI: fixed incorrect or duplicate stub output.
Following 3518:eb3aaf8bd2a9 (0.8.37), r->request_output is only set
if there are data in the first buffer sent in the subrequest. As a
result, following the change mentioned this flag cannot be used to
prevent duplicate ngx_http_ssi_stub_output() calls, since it is not
set if there was already some output, but the first buffer was empty.
Still, when there are multiple subrequests, even an empty subrequest
response might be delayed by the postpone filter, leading to a second
call of ngx_http_ssi_stub_output() during finalization from
ngx_http_writer() the subreqest buffers are released by the postpone
filter. Since r->request_output is not set after the first call, this
resulted in duplicate stub output.
Additionally, checking only the first buffer might be wrong in some
unusual cases. For example, the first buffer might be empty if
$r->flush() is called before printing any data in the embedded Perl
module.
Depending on the postpone_output value and corresponding sizes, this
issue can result in either duplicate or unexpected stub output, or
"zero size buf in writer" alerts.
Following 8124:f5515e727656 (1.23.4), it became slightly easier to
reproduce the issue, as empty static files and empty cache items now
result in a response with an empty buffer. Before the change, an empty
proxied response can be used to reproduce the issue.
Fix is check all buffers and set r->request_output if any non-empty
buffers are sent. This ensures that all unusual cases of non-empty
responses are covered, and also that r->request_output will be set
after the first stub output, preventing duplicate output.
Reported by Jan Gassen.
author | Maxim Dounin <mdounin@mdounin.ru> |
---|---|
date | Thu, 04 Jul 2024 17:41:28 +0300 |
parents | 2706b60dc225 |
children |
line wrap: on
line source
/* * Copyright (C) Igor Sysoev * Copyright (C) Nginx, Inc. */ #include <ngx_config.h> #include <ngx_core.h> static ngx_int_t ngx_log_check_rate(ngx_log_t *log, ngx_uint_t level); static char *ngx_error_log(ngx_conf_t *cf, ngx_command_t *cmd, void *conf); static char *ngx_log_set_params(ngx_conf_t *cf, ngx_log_t *log); static void ngx_log_insert(ngx_log_t *log, ngx_log_t *new_log); #if (NGX_DEBUG) static void ngx_log_memory_writer(ngx_log_t *log, ngx_uint_t level, u_char *buf, size_t len); static void ngx_log_memory_cleanup(void *data); typedef struct { u_char *start; u_char *end; u_char *pos; ngx_atomic_t written; } ngx_log_memory_buf_t; #endif static ngx_command_t ngx_errlog_commands[] = { { ngx_string("error_log"), NGX_MAIN_CONF|NGX_CONF_1MORE, ngx_error_log, 0, 0, NULL }, ngx_null_command }; static ngx_core_module_t ngx_errlog_module_ctx = { ngx_string("errlog"), NULL, NULL }; ngx_module_t ngx_errlog_module = { NGX_MODULE_V1, &ngx_errlog_module_ctx, /* module context */ ngx_errlog_commands, /* module directives */ NGX_CORE_MODULE, /* module type */ NULL, /* init master */ NULL, /* init module */ NULL, /* init process */ NULL, /* init thread */ NULL, /* exit thread */ NULL, /* exit process */ NULL, /* exit master */ NGX_MODULE_V1_PADDING }; static ngx_log_t ngx_log; static ngx_open_file_t ngx_log_file; ngx_uint_t ngx_use_stderr = 1; static ngx_str_t err_levels[] = { ngx_null_string, ngx_string("emerg"), ngx_string("alert"), ngx_string("crit"), ngx_string("error"), ngx_string("warn"), ngx_string("notice"), ngx_string("info"), ngx_string("debug") }; static const char *debug_levels[] = { "debug_core", "debug_alloc", "debug_mutex", "debug_event", "debug_http", "debug_mail", "debug_stream" }; #if (NGX_HAVE_VARIADIC_MACROS) void ngx_log_error_core(ngx_uint_t level, ngx_log_t *log, ngx_err_t err, const char *fmt, ...) #else void ngx_log_error_core(ngx_uint_t level, ngx_log_t *log, ngx_err_t err, const char *fmt, va_list args) #endif { #if (NGX_HAVE_VARIADIC_MACROS) va_list args; #endif u_char *p, *last, *msg; ssize_t n; ngx_uint_t wrote_stderr, debug_connection; u_char errstr[NGX_MAX_ERROR_STR]; last = errstr + NGX_MAX_ERROR_STR; p = ngx_cpymem(errstr, ngx_cached_err_log_time.data, ngx_cached_err_log_time.len); p = ngx_slprintf(p, last, " [%V] ", &err_levels[level]); /* pid#tid */ p = ngx_slprintf(p, last, "%P#" NGX_TID_T_FMT ": ", ngx_log_pid, ngx_log_tid); if (log->connection) { p = ngx_slprintf(p, last, "*%uA ", log->connection); } msg = p; #if (NGX_HAVE_VARIADIC_MACROS) va_start(args, fmt); p = ngx_vslprintf(p, last, fmt, args); va_end(args); #else p = ngx_vslprintf(p, last, fmt, args); #endif if (err) { p = ngx_log_errno(p, last, err); } if (level != NGX_LOG_DEBUG && log->handler) { p = log->handler(log, p, last - p); } if (p > last - NGX_LINEFEED_SIZE) { p = last - NGX_LINEFEED_SIZE; } ngx_linefeed(p); wrote_stderr = 0; debug_connection = (log->log_level & NGX_LOG_DEBUG_CONNECTION) != 0; while (log) { if (log->log_level < level && !debug_connection) { break; } if (log->limit && !debug_connection) { if (ngx_log_check_rate(log, level) == NGX_BUSY) { goto next; } } if (log->writer) { log->writer(log, level, errstr, p - errstr); goto next; } if (ngx_time() == log->file->disk_full_time) { /* * on FreeBSD writing to a full filesystem with enabled softupdates * may block process for much longer time than writing to non-full * filesystem, so we skip writing to a log for one second */ goto next; } n = ngx_write_fd(log->file->fd, errstr, p - errstr); if (n == -1 && ngx_errno == NGX_ENOSPC) { log->file->disk_full_time = ngx_time(); } if (log->file->fd == ngx_stderr) { wrote_stderr = 1; } next: log = log->next; } if (!ngx_use_stderr || level > NGX_LOG_WARN || wrote_stderr) { return; } msg -= (7 + err_levels[level].len + 3); (void) ngx_sprintf(msg, "nginx: [%V] ", &err_levels[level]); (void) ngx_write_console(ngx_stderr, msg, p - msg); } #if !(NGX_HAVE_VARIADIC_MACROS) void ngx_cdecl ngx_log_error(ngx_uint_t level, ngx_log_t *log, ngx_err_t err, const char *fmt, ...) { va_list args; if (log->log_level >= level) { va_start(args, fmt); ngx_log_error_core(level, log, err, fmt, args); va_end(args); } } void ngx_cdecl ngx_log_debug_core(ngx_log_t *log, ngx_err_t err, const char *fmt, ...) { va_list args; va_start(args, fmt); ngx_log_error_core(NGX_LOG_DEBUG, log, err, fmt, args); va_end(args); } #endif void ngx_cdecl ngx_log_abort(ngx_err_t err, const char *fmt, ...) { u_char *p; va_list args; u_char errstr[NGX_MAX_CONF_ERRSTR]; va_start(args, fmt); p = ngx_vsnprintf(errstr, sizeof(errstr) - 1, fmt, args); va_end(args); ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, err, "%*s", p - errstr, errstr); } void ngx_cdecl ngx_log_stderr(ngx_err_t err, const char *fmt, ...) { u_char *p, *last; va_list args; u_char errstr[NGX_MAX_ERROR_STR]; last = errstr + NGX_MAX_ERROR_STR; p = ngx_cpymem(errstr, "nginx: ", 7); va_start(args, fmt); p = ngx_vslprintf(p, last, fmt, args); va_end(args); if (err) { p = ngx_log_errno(p, last, err); } if (p > last - NGX_LINEFEED_SIZE) { p = last - NGX_LINEFEED_SIZE; } ngx_linefeed(p); (void) ngx_write_console(ngx_stderr, errstr, p - errstr); } u_char * ngx_log_errno(u_char *buf, u_char *last, ngx_err_t err) { if (buf > last - 50) { /* leave a space for an error code */ buf = last - 50; *buf++ = '.'; *buf++ = '.'; *buf++ = '.'; } #if (NGX_WIN32) buf = ngx_slprintf(buf, last, ((unsigned) err < 0x80000000) ? " (%d: " : " (%Xd: ", err); #else buf = ngx_slprintf(buf, last, " (%d: ", err); #endif buf = ngx_strerror(err, buf, last - buf); if (buf < last) { *buf++ = ')'; } return buf; } static ngx_int_t ngx_log_check_rate(ngx_log_t *log, ngx_uint_t level) { ngx_log_t temp_log; ngx_int_t excess, changed, burst; ngx_atomic_int_t ms; ngx_atomic_uint_t now, last; now = ngx_current_msec; last = log->limit->last; excess = log->limit->excess; ms = (ngx_atomic_int_t) (now - last); if (ms < -60000) { ms = 1; } else if (ms < 0) { ms = 0; } changed = excess - log->limit->rate * ms / 1000 + 1000; if (changed < 0) { changed = 0; } burst = (log->log_level - level + 1) * log->limit->rate; if (changed > burst) { if (excess <= burst) { ngx_atomic_fetch_add(&log->limit->excess, 1000); /* log message to this log only */ temp_log = *log; temp_log.connection = 0; temp_log.handler = NULL; temp_log.limit = NULL; temp_log.next = NULL; ngx_log_error(level, &temp_log, 0, "too many log messages, limiting"); } return NGX_BUSY; } if (ms > 0 && ngx_atomic_cmp_set(&log->limit->last, last, now)) { ngx_atomic_fetch_add(&log->limit->excess, changed - excess); } else { ngx_atomic_fetch_add(&log->limit->excess, 1000); } return NGX_OK; } ngx_log_t * ngx_log_init(u_char *prefix, u_char *error_log) { u_char *p, *name; size_t nlen, plen; ngx_log.file = &ngx_log_file; ngx_log.log_level = NGX_LOG_NOTICE; if (error_log == NULL) { error_log = (u_char *) NGX_ERROR_LOG_PATH; } name = error_log; nlen = ngx_strlen(name); if (nlen == 0) { ngx_log_file.fd = ngx_stderr; return &ngx_log; } p = NULL; #if (NGX_WIN32) if (name[1] != ':') { #else if (name[0] != '/') { #endif if (prefix) { plen = ngx_strlen(prefix); } else { #ifdef NGX_PREFIX prefix = (u_char *) NGX_PREFIX; plen = ngx_strlen(prefix); #else plen = 0; #endif } if (plen) { name = malloc(plen + nlen + 2); if (name == NULL) { return NULL; } p = ngx_cpymem(name, prefix, plen); if (!ngx_path_separator(*(p - 1))) { *p++ = '/'; } ngx_cpystrn(p, error_log, nlen + 1); p = name; } } ngx_log_file.fd = ngx_open_file(name, NGX_FILE_APPEND, NGX_FILE_CREATE_OR_OPEN, NGX_FILE_DEFAULT_ACCESS); if (ngx_log_file.fd == NGX_INVALID_FILE) { ngx_log_stderr(ngx_errno, "[alert] could not open error log file: " ngx_open_file_n " \"%s\" failed", name); #if (NGX_WIN32) ngx_event_log(ngx_errno, "could not open error log file: " ngx_open_file_n " \"%s\" failed", name); #endif ngx_log_file.fd = ngx_stderr; } if (p) { ngx_free(p); } return &ngx_log; } ngx_int_t ngx_log_open_default(ngx_cycle_t *cycle) { ngx_log_t *log; if (ngx_log_get_file_log(&cycle->new_log) != NULL) { return NGX_OK; } if (cycle->new_log.log_level != 0) { /* there are some error logs, but no files */ log = ngx_pcalloc(cycle->pool, sizeof(ngx_log_t)); if (log == NULL) { return NGX_ERROR; } } else { /* no error logs at all */ log = &cycle->new_log; } log->log_level = NGX_LOG_ERR; log->file = ngx_conf_open_file(cycle, &cycle->error_log); if (log->file == NULL) { return NGX_ERROR; } if (log != &cycle->new_log) { ngx_log_insert(&cycle->new_log, log); } return NGX_OK; } ngx_int_t ngx_log_redirect_stderr(ngx_cycle_t *cycle) { ngx_fd_t fd; if (cycle->log_use_stderr) { return NGX_OK; } /* file log always exists when we are called */ fd = ngx_log_get_file_log(cycle->log)->file->fd; if (fd != ngx_stderr) { if (ngx_set_stderr(fd) == NGX_FILE_ERROR) { ngx_log_error(NGX_LOG_ALERT, cycle->log, ngx_errno, ngx_set_stderr_n " failed"); return NGX_ERROR; } } return NGX_OK; } ngx_log_t * ngx_log_get_file_log(ngx_log_t *head) { ngx_log_t *log; for (log = head; log; log = log->next) { if (log->file != NULL) { return log; } } return NULL; } static char * ngx_error_log(ngx_conf_t *cf, ngx_command_t *cmd, void *conf) { ngx_log_t *dummy; dummy = &cf->cycle->new_log; return ngx_log_set_log(cf, &dummy); } char * ngx_log_set_log(ngx_conf_t *cf, ngx_log_t **head) { ngx_log_t *new_log; ngx_str_t *value, name; ngx_syslog_peer_t *peer; if (*head != NULL && (*head)->log_level == 0) { new_log = *head; } else { new_log = ngx_pcalloc(cf->pool, sizeof(ngx_log_t)); if (new_log == NULL) { return NGX_CONF_ERROR; } if (*head == NULL) { *head = new_log; } } value = cf->args->elts; if (ngx_strcmp(value[1].data, "stderr") == 0) { ngx_str_null(&name); cf->cycle->log_use_stderr = 1; new_log->file = ngx_conf_open_file(cf->cycle, &name); if (new_log->file == NULL) { return NGX_CONF_ERROR; } } else if (ngx_strncmp(value[1].data, "memory:", 7) == 0) { #if (NGX_DEBUG) size_t size, needed; ngx_pool_cleanup_t *cln; ngx_log_memory_buf_t *buf; value[1].len -= 7; value[1].data += 7; needed = sizeof("MEMLOG :" NGX_LINEFEED) + cf->conf_file->file.name.len + NGX_SIZE_T_LEN + NGX_INT_T_LEN + NGX_MAX_ERROR_STR; size = ngx_parse_size(&value[1]); if (size == (size_t) NGX_ERROR || size < needed) { ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "invalid buffer size \"%V\"", &value[1]); return NGX_CONF_ERROR; } buf = ngx_pcalloc(cf->pool, sizeof(ngx_log_memory_buf_t)); if (buf == NULL) { return NGX_CONF_ERROR; } buf->start = ngx_pnalloc(cf->pool, size); if (buf->start == NULL) { return NGX_CONF_ERROR; } buf->end = buf->start + size; buf->pos = ngx_slprintf(buf->start, buf->end, "MEMLOG %uz %V:%ui%N", size, &cf->conf_file->file.name, cf->conf_file->line); ngx_memset(buf->pos, ' ', buf->end - buf->pos); cln = ngx_pool_cleanup_add(cf->pool, 0); if (cln == NULL) { return NGX_CONF_ERROR; } cln->data = new_log; cln->handler = ngx_log_memory_cleanup; new_log->writer = ngx_log_memory_writer; new_log->wdata = buf; #else ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "nginx was built without debug support"); return NGX_CONF_ERROR; #endif } else if (ngx_strncmp(value[1].data, "syslog:", 7) == 0) { peer = ngx_pcalloc(cf->pool, sizeof(ngx_syslog_peer_t)); if (peer == NULL) { return NGX_CONF_ERROR; } if (ngx_syslog_process_conf(cf, peer) != NGX_CONF_OK) { return NGX_CONF_ERROR; } new_log->writer = ngx_syslog_writer; new_log->wdata = peer; } else { new_log->file = ngx_conf_open_file(cf->cycle, &value[1]); if (new_log->file == NULL) { return NGX_CONF_ERROR; } } if (ngx_log_set_params(cf, new_log) != NGX_CONF_OK) { return NGX_CONF_ERROR; } if (*head != new_log) { ngx_log_insert(*head, new_log); } return NGX_CONF_OK; } static char * ngx_log_set_params(ngx_conf_t *cf, ngx_log_t *log) { size_t len; ngx_int_t rate; ngx_uint_t i, n, d; ngx_str_t *value; value = cf->args->elts; rate = 1000; for (i = 2; i < cf->args->nelts; i++) { for (n = 1; n <= NGX_LOG_DEBUG; n++) { if (ngx_strcmp(value[i].data, err_levels[n].data) == 0) { if (log->log_level != 0) { ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "duplicate log level \"%V\"", &value[i]); return NGX_CONF_ERROR; } log->log_level = n; goto next; } } for (n = 0, d = NGX_LOG_DEBUG_FIRST; d <= NGX_LOG_DEBUG_LAST; d <<= 1) { if (ngx_strcmp(value[i].data, debug_levels[n++]) == 0) { if (log->log_level & ~NGX_LOG_DEBUG_ALL) { ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "invalid log level \"%V\"", &value[i]); return NGX_CONF_ERROR; } log->log_level |= d; goto next; } } if (ngx_strncmp(value[i].data, "rate=", 5) == 0) { len = value[i].len; if (ngx_strncmp(value[i].data + len - 3, "m/s", 3) == 0) { len -= 3; } rate = ngx_atoi(value[i].data + 5, len - 5); if (rate < 0) { ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "invalid rate \"%V\"", &value[i]); return NGX_CONF_ERROR; } continue; } if (log->log_level) { ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "invalid parameter \"%V\"", &value[i]); } else { ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, "invalid log level \"%V\"", &value[i]); } return NGX_CONF_ERROR; next: continue; } if (log->log_level == 0) { log->log_level = NGX_LOG_ERR; } if (log->log_level == NGX_LOG_DEBUG) { log->log_level = NGX_LOG_DEBUG_ALL; } if (rate > 0 && log->log_level < NGX_LOG_DEBUG) { log->limit = ngx_pcalloc(cf->pool, sizeof(ngx_log_limit_t)); if (log->limit == NULL) { return NGX_CONF_ERROR; } log->limit->rate = rate * 1000; } return NGX_CONF_OK; } static void ngx_log_insert(ngx_log_t *log, ngx_log_t *new_log) { ngx_log_t tmp; if (new_log->log_level > log->log_level) { /* * list head address is permanent, insert new log after * head and swap its contents with head */ tmp = *log; *log = *new_log; *new_log = tmp; log->next = new_log; return; } while (log->next) { if (new_log->log_level > log->next->log_level) { new_log->next = log->next; log->next = new_log; return; } log = log->next; } log->next = new_log; } #if (NGX_DEBUG) static void ngx_log_memory_writer(ngx_log_t *log, ngx_uint_t level, u_char *buf, size_t len) { u_char *p; size_t avail, written; ngx_log_memory_buf_t *mem; mem = log->wdata; if (mem == NULL) { return; } written = ngx_atomic_fetch_add(&mem->written, len); p = mem->pos + written % (mem->end - mem->pos); avail = mem->end - p; if (avail >= len) { ngx_memcpy(p, buf, len); } else { ngx_memcpy(p, buf, avail); ngx_memcpy(mem->pos, buf + avail, len - avail); } } static void ngx_log_memory_cleanup(void *data) { ngx_log_t *log = data; ngx_log_debug0(NGX_LOG_DEBUG_CORE, log, 0, "destroy memory log buffer"); log->wdata = NULL; } #endif