diff --git a/sapi/fpm/fpm/fpm_log.c b/sapi/fpm/fpm/fpm_log.c index 6619b7c26f064..d71e6ef0a8ffb 100644 --- a/sapi/fpm/fpm/fpm_log.c +++ b/sapi/fpm/fpm/fpm_log.c @@ -24,6 +24,7 @@ static char *fpm_log_format = NULL; static int fpm_log_fd = -1; static struct key_value_s *fpm_access_suppress_paths = NULL; +static struct zlog_stream fpm_log_stream; static int fpm_access_log_suppress(struct fpm_scoreboard_proc_s *proc); @@ -92,7 +93,7 @@ int fpm_log_init_child(struct fpm_worker_pool_s *wp) /* {{{ */ if (fpm_log_fd == -1) { fpm_log_fd = wp->log_fd; } - + zlog_stream_init_ex(&fpm_log_stream, ZLOG_ACCESS_LOG, fpm_log_fd); for (wp = fpm_worker_all_pools; wp; wp = wp->next) { if (wp->log_fd > -1 && wp->log_fd != fpm_log_fd) { @@ -107,12 +108,11 @@ int fpm_log_init_child(struct fpm_worker_pool_s *wp) /* {{{ */ int fpm_log_write(char *log_format) /* {{{ */ { - char *s, *b; - char buffer[FPM_LOG_BUFFER+1]; - int token, test; - size_t len, len2; + char *s; + bool test, token = false; struct fpm_scoreboard_proc_s proc, *proc_p; struct fpm_scoreboard_s *scoreboard; + struct zlog_stream *stream; char tmp[129]; char format[129]; time_t now_epoch; @@ -126,9 +126,9 @@ int fpm_log_write(char *log_format) /* {{{ */ if (!log_format) { log_format = fpm_log_format; - test = 0; + test = false; } else { - test = 1; + test = true; } now_epoch = time(NULL); @@ -152,38 +152,25 @@ int fpm_log_write(char *log_format) /* {{{ */ } } - token = 0; - - memset(buffer, '\0', sizeof(buffer)); - b = buffer; - len = 0; - s = log_format; + stream = &fpm_log_stream; + zlog_stream_start(stream); while (*s != '\0') { - /* Test is we have place for 1 more char. */ - if (len >= FPM_LOG_BUFFER) { - zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER); - len = FPM_LOG_BUFFER; - break; - } - if (!token && *s == '%') { - token = 1; + token = false; memset(format, '\0', sizeof(format)); /* reset format */ s++; continue; } if (token) { - token = 0; - len2 = 0; + token = false; switch (*s) { case '%': /* '%' */ - *b = '%'; - len2 = 1; + zlog_stream_char(stream, '%'); break; #ifdef HAVE_TIMES @@ -207,7 +194,7 @@ int fpm_log_write(char *log_format) /* {{{ */ format[0] = '\0'; if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.2f", tms_total / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.cpu_duration.tv_usec / 1000000.) * 100.); + zlog_stream_format(stream, "%.2f", tms_total / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.cpu_duration.tv_usec / 1000000.) * 100.); } break; #endif @@ -216,7 +203,7 @@ int fpm_log_write(char *log_format) /* {{{ */ /* seconds */ if (format[0] == '\0' || !strcasecmp(format, "seconds")) { if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.); + zlog_stream_format(stream, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.); } /* milliseconds */ @@ -225,13 +212,13 @@ int fpm_log_write(char *log_format) /* {{{ */ !strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili") ) { if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.); + zlog_stream_format(stream, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.); } /* microseconds */ } else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) { if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", (unsigned long)(proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec)); + zlog_stream_format(stream, "%lu", (unsigned long)(proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec)); } } else { @@ -249,26 +236,26 @@ int fpm_log_write(char *log_format) /* {{{ */ if (!test) { char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format)); - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-"); + zlog_stream_cstr(stream, env ? env : "-"); } format[0] = '\0'; break; case 'f': /* script */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.script_filename ? proc.script_filename : "-"); + zlog_stream_cstr(stream, *proc.script_filename ? proc.script_filename : "-"); } break; case 'l': /* content length */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length); + zlog_stream_format(stream, "%zu", proc.content_length); } break; case 'm': /* method */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.request_method ? proc.request_method : "-"); + zlog_stream_cstr(stream, *proc.request_method ? proc.request_method : "-"); } break; @@ -276,19 +263,19 @@ int fpm_log_write(char *log_format) /* {{{ */ /* seconds */ if (format[0] == '\0' || !strcasecmp(format, "bytes")) { if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory); + zlog_stream_format(stream, "%zu", proc.memory); } /* kilobytes */ } else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) { if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024); + zlog_stream_format(stream, "%zu", proc.memory / 1024); } /* megabytes */ } else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) { if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024 / 1024); + zlog_stream_format(stream, "%zu", proc.memory / 1024 / 1024); } } else { @@ -300,7 +287,7 @@ int fpm_log_write(char *log_format) /* {{{ */ case 'n': /* pool name */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", scoreboard->pool[0] ? scoreboard->pool : "-"); + zlog_stream_cstr(stream, scoreboard->pool[0] ? scoreboard->pool : "-"); } break; @@ -314,6 +301,7 @@ int fpm_log_write(char *log_format) /* {{{ */ zend_llist_position pos; sapi_headers_struct *sapi_headers = &SG(sapi_headers); size_t format_len = strlen(format); + ssize_t written = 0; h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos); while (h) { @@ -339,14 +327,13 @@ int fpm_log_write(char *log_format) /* {{{ */ } header = h->header + format_len + 2; - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-"); + written += zlog_stream_cstr(stream, header && *header ? header : "-"); /* found, done */ break; } - if (!len2) { - len2 = 1; - *b = '-'; + if (!written) { + zlog_stream_char(stream, '-'); } } format[0] = '\0'; @@ -354,44 +341,44 @@ int fpm_log_write(char *log_format) /* {{{ */ case 'p': /* PID */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid()); + zlog_stream_format(stream, "%ld", (long)getpid()); } break; case 'P': /* PID */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid()); + zlog_stream_format(stream, "%ld", (long)getppid()); } break; case 'q': /* query_string */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string); + zlog_stream_cstr(stream, proc.query_string); } break; case 'Q': /* '?' */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.query_string ? "?" : ""); + zlog_stream_cstr(stream, *proc.query_string ? "?" : ""); } break; case 'r': /* request URI */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri); + zlog_stream_cstr(stream, proc.request_uri); } break; case 'R': /* remote IP address */ if (!test) { const char *tmp = fcgi_get_last_client_ip(); - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-"); + zlog_stream_cstr(stream, tmp ? tmp : "-"); } break; case 's': /* status */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code); + zlog_stream_format(stream, "%d", SG(sapi_headers).http_response_code); } break; @@ -409,14 +396,14 @@ int fpm_log_write(char *log_format) /* {{{ */ } else { strftime(tmp, sizeof(tmp) - 1, format, localtime(t)); } - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp); + zlog_stream_cstr(stream, tmp); } format[0] = '\0'; break; case 'u': /* remote user */ if (!test) { - len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.auth_user); + zlog_stream_cstr(stream, proc.auth_user); } break; @@ -459,30 +446,28 @@ int fpm_log_write(char *log_format) /* {{{ */ return -1; } s++; - if (!test) { - b += len2; - len += len2; - } - if (len >= FPM_LOG_BUFFER) { - zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER); - len = FPM_LOG_BUFFER; + + if (zlog_stream_is_over_limit(stream)) { + zlog(ZLOG_NOTICE, "the log buffer is over the configured limit. The access log request has been truncated."); break; } continue; } + if (zlog_stream_is_over_limit(stream)) { + zlog(ZLOG_NOTICE, "the log buffer is over the configured limit. The access log request has been truncated."); + break; + } + if (!test) { // push the normal char to the output buffer - *b = *s; - b++; - len++; + zlog_stream_char(stream, *s); } s++; } - if (!test && strlen(buffer) > 0) { - buffer[len] = '\n'; - zend_quiet_write(fpm_log_fd, buffer, len + 1); + if (!test) { + zlog_stream_finish(stream); } return 0; diff --git a/sapi/fpm/fpm/zlog.c b/sapi/fpm/fpm/zlog.c index 39c6eec885bcd..bb648bf72c3ea 100644 --- a/sapi/fpm/fpm/zlog.c +++ b/sapi/fpm/fpm/zlog.c @@ -410,8 +410,16 @@ static inline ssize_t zlog_stream_unbuffered_write( } /* }}} */ -static inline ssize_t zlog_stream_buf_copy_cstr( - struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */ +void zlog_stream_start(struct zlog_stream *stream) +{ + stream->finished = 0; + stream->len = 0; + stream->full = 0; + stream->over_limit = 0; +} + +static ssize_t zlog_stream_buf_copy_cstr( + struct zlog_stream *stream, const char *str, size_t str_len) { ZEND_ASSERT(stream->len <= stream->buf.size); if (stream->buf.size - stream->len <= str_len && @@ -419,25 +427,32 @@ static inline ssize_t zlog_stream_buf_copy_cstr( return -1; } + if (stream->buf.size - stream->len <= str_len) { + stream->over_limit = 1; + str_len = stream->buf.size - stream->len; + } memcpy(stream->buf.data + stream->len, str, str_len); stream->len += str_len; return str_len; } -/* }}} */ -static inline ssize_t zlog_stream_buf_copy_char(struct zlog_stream *stream, char c) /* {{{ */ +static ssize_t zlog_stream_buf_copy_char(struct zlog_stream *stream, char c) { ZEND_ASSERT(stream->len <= stream->buf.size); - if (stream->buf.size - stream->len < 1 && !zlog_stream_buf_alloc_ex(stream, 1)) { + if (stream->buf.size == stream->len && !zlog_stream_buf_alloc_ex(stream, 1)) { return -1; } + if (stream->buf.size == stream->len) { + stream->over_limit = 1; + return 0; + } + stream->buf.data[stream->len++] = c; return 1; } -/* }}} */ static ssize_t zlog_stream_buf_flush(struct zlog_stream *stream) /* {{{ */ { @@ -466,8 +481,8 @@ static ssize_t zlog_stream_buf_flush(struct zlog_stream *stream) /* {{{ */ static ssize_t zlog_stream_buf_append( struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */ { - int over_limit = 0; size_t available_len, required_len, reserved_len; + int over_limit = 1; if (stream->len == 0) { stream->len = zlog_stream_prefix_ex(stream, stream->function, stream->line); @@ -477,7 +492,7 @@ static ssize_t zlog_stream_buf_append( reserved_len = stream->len + stream->msg_suffix_len + stream->msg_quote; required_len = reserved_len + str_len; if (required_len >= zlog_limit) { - over_limit = 1; + stream->over_limit = over_limit = 1; available_len = zlog_limit - reserved_len - 1; } else { available_len = str_len; @@ -487,7 +502,7 @@ static ssize_t zlog_stream_buf_append( return -1; } - if (!over_limit) { + if (over_limit) { return available_len; } @@ -521,16 +536,22 @@ static inline void zlog_stream_init_internal( stream->flags = flags; stream->use_syslog = fd == ZLOG_SYSLOG; stream->use_fd = fd > 0; - stream->use_buffer = zlog_buffering || external_logger != NULL || stream->use_syslog; - stream->buf_init_size = capacity; - stream->use_stderr = fd < 0 || - ( - fd != STDERR_FILENO && fd != STDOUT_FILENO && !launched && - (flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE - ); - stream->prefix_buffer = (flags & ZLOG_LEVEL_MASK) >= zlog_level && - (stream->use_fd || stream->use_stderr || stream->use_syslog); stream->fd = fd > -1 ? fd : STDERR_FILENO; + stream->buf_init_size = capacity; + if (flags & ZLOG_ACCESS_LOG) { + stream->use_buffer = 1; + stream->use_stderr = fd < 0; + } else { + stream->use_buffer = zlog_buffering || external_logger != NULL || stream->use_syslog; + stream->buf_init_size = capacity; + stream->use_stderr = fd < 0 || + ( + fd != STDERR_FILENO && fd != STDOUT_FILENO && !launched && + (flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE + ); + stream->prefix_buffer = (flags & ZLOG_LEVEL_MASK) >= zlog_level && + (stream->use_fd || stream->use_stderr || stream->use_syslog); + } } /* }}} */ @@ -745,7 +766,7 @@ ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...) /* } /* }}} */ -ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */ +ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len) { /* do not write anything if the stream is full or str is empty */ if (str_len == 0 || stream->full) { @@ -754,9 +775,7 @@ ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_ /* reset stream if it is finished */ if (stream->finished) { - stream->finished = 0; - stream->len = 0; - stream->full = 0; + zlog_stream_start(stream); } if (stream->use_buffer) { @@ -765,7 +784,25 @@ ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_ return zlog_stream_unbuffered_write(stream, str, str_len); } -/* }}} */ + +ssize_t zlog_stream_char(struct zlog_stream *stream, char c) +{ + /* do not write anything if the stream is full */ + if (stream->full) { + return 0; + } + + /* reset stream if it is finished */ + if (stream->finished) { + zlog_stream_start(stream); + } + + if (stream->use_buffer) { + return zlog_stream_buf_copy_char(stream, c); + } + const char tmp[1] = {c}; + return zlog_stream_direct_write(stream, tmp, 1); +} static inline void zlog_stream_finish_buffer_suffix(struct zlog_stream *stream) /* {{{ */ { @@ -883,3 +920,8 @@ zlog_bool zlog_stream_close(struct zlog_stream *stream) /* {{{ */ return finished; } /* }}} */ + +zlog_bool zlog_stream_is_over_limit(struct zlog_stream *stream) +{ + return stream->over_limit; +} diff --git a/sapi/fpm/fpm/zlog.h b/sapi/fpm/fpm/zlog.h index be22acc32f3ca..6886a0ae807da 100644 --- a/sapi/fpm/fpm/zlog.h +++ b/sapi/fpm/fpm/zlog.h @@ -48,6 +48,8 @@ enum { #define ZLOG_LEVEL_MASK 7 +#define ZLOG_ACCESS_LOG 16 + #define ZLOG_HAVE_ERRNO 0x100 #define ZLOG_SYSERROR (ZLOG_ERROR | ZLOG_HAVE_ERRNO) @@ -74,6 +76,7 @@ struct zlog_stream { unsigned int msg_quote:1; unsigned int decorate:1; unsigned int is_stdout:1; + unsigned int over_limit:1; int fd; int line; int child_pid; @@ -103,14 +106,22 @@ zlog_bool zlog_stream_set_msg_suffix( struct zlog_stream *stream, const char *suffix, const char *final_suffix); #define zlog_stream_prefix(stream) \ zlog_stream_prefix_ex(stream, __func__, __LINE__) +void zlog_stream_start(struct zlog_stream *stream); ssize_t zlog_stream_prefix_ex(struct zlog_stream *stream, const char *function, int line); ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...) __attribute__ ((format(printf,2,3))); ssize_t zlog_stream_vformat(struct zlog_stream *stream, const char *fmt, va_list args); ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len); +ssize_t zlog_stream_char(struct zlog_stream *stream, char c); zlog_bool zlog_stream_finish(struct zlog_stream *stream); void zlog_stream_destroy(struct zlog_stream *stream); zlog_bool zlog_stream_close(struct zlog_stream *stream); +zlog_bool zlog_stream_is_over_limit(struct zlog_stream *stream); + +static inline ssize_t zlog_stream_cstr(struct zlog_stream *stream, const char *cstr) +{ + return zlog_stream_str(stream, cstr, strlen(cstr)); +} /* default log limit */ #define ZLOG_DEFAULT_LIMIT 1024