FPM: Implement configurable access log limit

It sets the access log limit as configurable log_limit to allow larger
log limit than the currently fixed limit of 1024 characters.

Fixes GH-12302
Closes GH-18725

Author: bukka

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,8 @@ 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);
+	zlog_stream_set_wrapping(&fpm_log_stream, 0);
 
 	for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
 		if (wp->log_fd > -1 && wp->log_fd != fpm_log_fd) {
@@ -107,12 +109,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 +127,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 +153,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 = true;
 			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 +195,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 +204,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 +213,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,46 +237,46 @@ 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;
 
 				case 'M': /* memory */
 					/* 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 +288,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 +302,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,59 +328,58 @@ 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';
 					break;
 
 				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 +397,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 +447,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;

sapi/fpm/fpm/fpm_scoreboard.h

@@ -34,11 +34,11 @@ struct fpm_scoreboard_proc_s {
 	struct timeval duration;
 	time_t accepted_epoch;
 	struct timeval tv;
-	char request_uri[128];
-	char query_string[512];
+	char request_uri[512];
+	char query_string[2048];
 	char request_method[16];
 	size_t content_length; /* used with POST only */
-	char script_filename[256];
+	char script_filename[512];
 	char auth_user[32];
 #ifdef HAVE_TIMES
 	struct tms cpu_accepted;