Add "result" argument to log() function

docs/UserManual.md

@@ -1088,12 +1088,18 @@ some features of the "mg" library are not available yet. Use the "start()" callb
 function instead.
 
 A Lua background script may define the following functions:
-    `start()`      -- called wnen the server is started
-    `stop()`       -- called when the server is stopped
-    `log(request_info)`  -- called when an access log entry is created
+    `start()`        -- called wnen the server is started
+    `stop()`         -- called when the server is stopped
+    `log(req, res)`  -- called when an access log entry is created
 
 The optional function `log` may be used to filter or format access log file entries.
 The `request_info` table is supplied as first argument (content of this table: see above).
+The second argument is the request processing result. It contains the number of bytes
+`read` and `written` (incl. header information), the `processing_time` in seconds, 
+the `protocol` ("http", "https", "ws" or "wss"). For internally generated response and
+response generated using the `mg_response_*()` API, it will contain the http `status` 
+code and a the response `http_headers` table (CGI response will not have all headers).
+
 The function can return a boolean value: true if the entry should be logged or false if not.
 Alternatively it can return a string: this will be used as log message
 (empty strings will not be logged).

src/civetweb.c

@@ -2627,6 +2627,7 @@ struct mg_connection {
 #if defined(USE_SERVER_STATS)
 	time_t conn_close_time; /* Time (wall clock) when connection was
 	                         * closed (or 0 if still open) */
+	double processing_time; /* Procesing time for one request. */
 #endif
 	struct timespec req_time; /* Time (since system start) when the request
 	                           * was received */
@@ -6678,6 +6679,40 @@ mg_read_inner(struct mg_connection *conn, void *buf, size_t len)
 
 /* Forward declarations */
 static void handle_request(struct mg_connection *);
+static void log_access(const struct mg_connection *);
+
+
+/* Handle request, update statistics and call access log */
+static void
+handle_request_stat_log(struct mg_connection *conn)
+{
+#if defined(USE_SERVER_STATS)
+	struct timespec tnow;
+	conn->conn_state = 4; /* processing */
+#endif
+
+	handle_request(conn);
+
+
+#if defined(USE_SERVER_STATS)
+	conn->conn_state = 5; /* processed */
+
+	mg_clock_gettime(CLOCK_MONOTONIC, &tnow);
+	conn->processing_time = mg_difftimespec(&tnow, &(conn->req_time));
+
+	mg_atomic_add64(&(conn->phys_ctx->total_data_read), conn->consumed_content);
+	mg_atomic_add64(&(conn->phys_ctx->total_data_written),
+	                conn->num_bytes_sent);
+#endif
+
+	DEBUG_TRACE("%s", "handle_request done");
+
+	if (conn->phys_ctx->callbacks.end_request != NULL) {
+		conn->phys_ctx->callbacks.end_request(conn, conn->status_code);
+		DEBUG_TRACE("%s", "end_request callback done");
+	}
+	log_access(conn);
+}
 
 
 #if defined(USE_HTTP2)
@@ -15257,7 +15292,6 @@ header_val(const struct mg_connection *conn, const char *header)
 
 
 #if defined(MG_EXTERNAL_FUNCTION_log_access)
-static void log_access(const struct mg_connection *conn);
 #include "external_log_access.inl"
 #elif !defined(NO_FILESYSTEMS)
 
@@ -15290,8 +15324,9 @@ log_access(const struct mg_connection *conn)
 		/* call "log()" in Lua */
 		lua_getglobal(lstate, "log");
 		prepare_lua_request_info_inner(conn, lstate);
+		push_lua_response_log_data(conn, lstate);
 
-		ret = lua_pcall(lstate, /* args */ 1, /* results */ 1, 0);
+		ret = lua_pcall(lstate, /* args */ 2, /* results */ 1, 0);
 		if (ret == 0) {
 			int t = lua_type(lstate, -1);
 			if (t == LUA_TBOOLEAN) {
@@ -16891,6 +16926,10 @@ reset_per_request_attributes(struct mg_connection *conn)
 	}
 	conn->request_info.local_uri = NULL;
 
+#if defined(USE_SERVER_STATS)
+	conn->processing_time = 0;
+#endif
+
 #if defined(MG_LEGACY_INTERFACE)
 	/* Legacy before split into local_uri and request_uri */
 	conn->request_info.uri = NULL;
@@ -17712,6 +17751,7 @@ get_message(struct mg_connection *conn, char *ebuf, size_t ebuf_len, int *err)
 		*err = 500;
 		return 0;
 	}
+
 	/* Set the time the request was received. This value should be used for
 	 * timeouts. */
 	clock_gettime(CLOCK_MONOTONIC, &(conn->req_time));
@@ -18598,28 +18638,7 @@ process_new_connection(struct mg_connection *conn)
 			if (conn->request_info.local_uri) {
 
 				/* handle request to local server */
-#if defined(USE_SERVER_STATS)
-				conn->conn_state = 4; /* processing */
-#endif
-				handle_request(conn);
-
-#if defined(USE_SERVER_STATS)
-				conn->conn_state = 5; /* processed */
-
-				mg_atomic_add64(&(conn->phys_ctx->total_data_read),
-				                conn->consumed_content);
-				mg_atomic_add64(&(conn->phys_ctx->total_data_written),
-				                conn->num_bytes_sent);
-#endif
-
-				DEBUG_TRACE("%s", "handle_request done");
-
-				if (conn->phys_ctx->callbacks.end_request != NULL) {
-					conn->phys_ctx->callbacks.end_request(conn,
-					                                      conn->status_code);
-					DEBUG_TRACE("%s", "end_request callback done");
-				}
-				log_access(conn);
+				handle_request_stat_log(conn);
 
 			} else {
 				/* TODO: handle non-local request (PROXY) */

src/mod_http2.inl

@@ -1272,6 +1272,10 @@ handle_http2(struct mg_connection *conn)
 		int frame_is_padded = 0;
 		int frame_is_priority = 0;
 
+#if defined(USE_SERVER_STATS)
+		conn->conn_state = 3; /* HTTP/2 ready */
+#endif
+
 		bytes_read = mg_read(conn, http2_frame_head, sizeof(http2_frame_head));
 		if (bytes_read != sizeof(http2_frame_head)) {
 			/* TODO: errormsg */
@@ -1333,6 +1337,9 @@ handle_http2(struct mg_connection *conn)
 			uint8_t weight = 0;
 			uint8_t exclusive = 0;
 
+			/* Request start time */
+			clock_gettime(CLOCK_MONOTONIC, &(conn->req_time));
+
 			if (frame_is_padded) {
 				padding = buf[i];
 				i++;
@@ -1569,7 +1576,7 @@ handle_http2(struct mg_connection *conn)
 			/* header parsed */
 			DEBUG_TRACE("HTTP2 handle_request (stream %u)",
 			            http2_frame_stream_id);
-			handle_request(conn);
+			handle_request_stat_log(conn);
 
 			/* Send "final" frame */
 			DEBUG_TRACE("HTTP2 handle_request done (stream %u)",

src/mod_lua.inl

@@ -119,6 +119,34 @@ reg_int(struct lua_State *L, const char *name, int val)
 
 
 static void
+reg_i64(struct lua_State *L, const char *name, int64_t val)
+{
+	if (name == NULL) {
+		return;
+	}
+	lua_pushstring(L, name);
+	if (sizeof(lua_Integer) >= sizeof(val)) {
+		lua_pushinteger(L, (lua_Integer)val);
+	} else {
+		double d = (double)val;
+		lua_pushnumber(L, d);
+	}
+	lua_rawset(L, -3);
+}
+
+
+static void
+reg_double(struct lua_State *L, const char *name, double val)
+{
+	if (name != NULL) {
+		lua_pushstring(L, name);
+		lua_pushnumber(L, val);
+		lua_rawset(L, -3);
+	}
+}
+
+
+static void
 reg_boolean(struct lua_State *L, const char *name, int val)
 {
 	if (name != NULL) {
@@ -2458,6 +2486,45 @@ enum {
 
 
 static void
+push_lua_response_log_data(const struct mg_connection *conn, lua_State *L)
+{
+	int i;
+	const char *s;
+
+	lua_newtable(L);
+
+	/* request status */
+	reg_int(L, "status", conn->status_code);
+
+	/* protocol (http, https, ws, wss) */
+	s = get_proto_name(conn);
+	reg_string(L, "protocol", s);
+
+	/* request counter */
+	reg_int(L, "handled_requests", conn->handled_requests);
+
+	/* data read and written */
+	reg_i64(L, "read", conn->consumed_content);
+	reg_i64(L, "written", conn->num_bytes_sent);
+
+#if !defined(NO_RESPONSE_BUFFERING)
+	lua_pushstring(L, "http_headers");
+	lua_newtable(L);
+	for (i = 0; i < conn->response_info.num_headers; i++) {
+		reg_string(L,
+		           conn->response_info.http_headers[i].name,
+		           conn->response_info.http_headers[i].value);
+	}
+	lua_rawset(L, -3);
+#endif
+
+#if defined(USE_SERVER_STATS)
+	reg_double(L, "processing_time", conn->processing_time);
+#endif
+}
+
+
+static void
 prepare_lua_request_info_inner(const struct mg_connection *conn, lua_State *L)
 {
 	const char *s;

src/response.inl

@@ -8,7 +8,7 @@
  */
 
 #if defined(NO_RESPONSE_BUFFERING) && defined(USE_HTTP2)
-#error "HTTP2 currently works only if NO_RESPONSE_BUFFERING is not set"
+#error "HTTP2 works only if NO_RESPONSE_BUFFERING is not set"
 #endif
 
 
@@ -241,7 +241,7 @@ mg_response_header_add_lines(struct mg_connection *conn,
 }
 
 
-#if defined USE_HTTP2
+#if defined(USE_HTTP2)
 static int http2_send_response_headers(struct mg_connection *conn);
 #endif
 
@@ -282,14 +282,12 @@ mg_response_header_send(struct mg_connection *conn)
 	conn->request_state = 2;
 
 #if !defined(NO_RESPONSE_BUFFERING)
+#if defined(USE_HTTP2)
 	if (conn->protocol_type == PROTOCOL_TYPE_HTTP2) {
-#if defined USE_HTTP2
 		int ret = http2_send_response_headers(conn);
 		return ret ? 0 : 0; /* todo */
-#else
-		return -2;
-#endif
 	}
+#endif
 
 	/* Send */
 	send_http1_response_status_line(conn);

test/lua_backbround_script_logging.lua

@@ -0,0 +1,52 @@
+
+function start()
+    -- The "start" function is called when the server is ready.
+	logfile = io.open("C:\\tmp\\lualog.txt", "w");
+	if (logfile) then
+	    logfile:write("Server start: " .. os.date('%Y-%m-%dT%H:%M:%S') .. "\n\n");
+	end
+end
+
+
+function stop()
+    -- The "stop" function is called when the server is stopping.
+    logfile:close();
+end
+
+
+function log(req, resp)
+    -- The "log" function can be used to
+	-- (a) filter messages and return boolean: true (log) or false (do not log)
+	-- (b) format log message and return it as string (empty string will not log)
+	-- (c) forward the log data to an external log
+
+	if logfile then
+	  logfile:write(os.date('%Y-%m-%dT%H:%M:%S').."\n");
+	  logfile:write("request:\n");
+	  for k,v in pairs(req) do
+	    logfile:write("  " .. tostring(k) .. " = " .. tostring(v) .. "\n");
+		if type(v) == "table" then
+		  for k2,v2 in pairs(v) do
+	        logfile:write("    " .. tostring(k2) .. " = " .. tostring(v2) .. "\n");
+		  end
+		end
+	  end
+	  logfile:write("response:\n");
+	  for k,v in pairs(resp) do
+	    logfile:write("  " .. tostring(k) .. " = " .. tostring(v) .. "\n");
+		if type(v) == "table" then
+		  for k2,v2 in pairs(v) do
+	        logfile:write("    " .. tostring(k2) .. " = " .. tostring(v2) .. "\n");
+		  end
+		end
+	  end
+	  logfile:write("----\n\n");
+	  logfile:flush();
+	end
+
+	-- Loging already done here
+	return false;
+end
+
+-- Return true to continue server startup.
+return true;