Revamp ic-proxy logging

This is a follow-up to 24140214f21, which was reverted for being too
verbose by default, causing CI failures. This reintroduces the
gp_log_interconnect GUC to ic-proxy logging and follows the
specifications outlined in cdbvars.c. The ic_proxy_log macro is replaced
with elog and elogif for WARNINGs/ERRORs and other events respectively.

The scheme used:
TERSE[LOG]:     Server main loop events, signals
VERBOSE[LOG]:   Startup, (un)register, close/shutdown, EOF receipt etc.
DEBUG[DEBUG1]:  Special packet (BYE/HELLO) transfer, pause/resume events
DEBUG[DEBUG3]:  Less interesting packet transfers, caching
DEBUG[DEBUG5]:  Very low-level tracing info

Author: soumyadeep2007

contrib/interconnect/proxy/ic_proxy.h

@@ -29,22 +29,10 @@
 /* send a ack message after a batch of packets*/
 #define IC_PROXY_ACK_INTERVAL 10
 
-
-#ifndef IC_PROXY_LOG_LEVEL
-#define IC_PROXY_LOG_LEVEL WARNING
-#endif
-
 #define ic_proxy_alloc(size) palloc(size)
 #define ic_proxy_free(ptr) pfree(ptr)
 #define ic_proxy_new(type) ((type *) ic_proxy_alloc(sizeof(type)))
 
-#define ic_proxy_log(elevel, msg...) do { \
-	if (elevel >= IC_PROXY_LOG_LEVEL) \
-	{ \
-		elog(elevel, msg); \
-	} \
-} while (0)
-
 /*
  * Build the domain socket path.
  *

contrib/interconnect/proxy/ic_proxy_addr.c

@@ -168,8 +168,8 @@ ic_proxy_addr_on_getaddrinfo(uv_getaddrinfo_t *req,
 			/* the req is cancelled, nothing to do */
 		}
 		else
-			ic_proxy_log(WARNING,
-						 "ic-proxy-addr: seg%d,dbid%d: fail to resolve the hostname \"%s\":%s: %s",
+			elog(WARNING,
+						 "ic-proxy: seg%d,dbid%d: fail to resolve the hostname \"%s\":%s: %s",
 						 addr->content, addr->dbid,
 						 addr->hostname, addr->service,
 						 uv_strerror(status));
@@ -186,7 +186,7 @@ ic_proxy_addr_on_getaddrinfo(uv_getaddrinfo_t *req,
 			if (iter->ai_family == AF_UNIX)
 				continue;
 
-#if IC_PROXY_LOG_LEVEL <= LOG
+			if (gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE)
 			{
 				char		name[HOST_NAME_MAX] = "unknown";
 				int			port = 0;
@@ -196,20 +196,19 @@ ic_proxy_addr_on_getaddrinfo(uv_getaddrinfo_t *req,
 				ret = ic_proxy_extract_sockaddr(iter->ai_addr, name, sizeof(name),
 											&port, &family);
 				if (ret == 0)
-					ic_proxy_log(LOG,
-								 "ic-proxy-addr: seg%d,dbid%d: resolved address %s:%s -> %s:%d family=%d",
+					elog(LOG,
+								 "ic-proxy: seg%d,dbid%d: resolved address %s:%s -> %s:%d family=%d",
 								 addr->content, addr->dbid,
 								 addr->hostname, addr->service,
 								 name, port, family);
 				else
-					ic_proxy_log(LOG,
-								 "ic-proxy-addr: seg%d,dbid%d: resolved address %s:%s -> %s:%d family=%d (fail to extract the address: %s)",
+					elog(LOG,
+								 "ic-proxy: seg%d,dbid%d: resolved address %s:%s -> %s:%d family=%d (fail to extract the address: %s)",
 								 addr->content, addr->dbid,
 								 addr->hostname, addr->service,
 								 name, port, family,
 								 uv_strerror(ret));
 			}
-#endif /* IC_PROXY_LOG_LEVEL <= LOG */
 
 			memcpy(&addr->sockaddr, iter->ai_addr, iter->ai_addrlen);
 			ic_proxy_addrs = lappend(ic_proxy_addrs, addr);
@@ -295,8 +294,8 @@ ic_proxy_reload_addresses(uv_loop_t *loop)
 			if (dbid == GpIdentity.dbid)
 				ic_proxy_my_addr = addr;
 
-			ic_proxy_log(LOG,
-						 "ic-proxy-addr: seg%d,dbid%d: parsed addr: %s:%d",
+			elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG,
+						 "ic-proxy: seg%d,dbid%d: parsed addr: %s:%d",
 						 content, dbid, hostname, port);
 
 			uv_getaddrinfo(loop, &addr->req, ic_proxy_addr_on_getaddrinfo,
@@ -326,7 +325,7 @@ ic_proxy_get_my_addr(void)
 	if (ic_proxy_my_addr)
 		return ic_proxy_my_addr;
 
-	ic_proxy_log(LOG, "ic-proxy-addr: cannot get my addr");
+	elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, "ic-proxy: cannot get my addr");
 	return NULL;
 }
 
@@ -343,8 +342,8 @@ ic_proxy_addr_get_port(const ICProxyAddr *addr)
 	else if (addr->sockaddr.ss_family == AF_INET6)
 		return ntohs(((struct sockaddr_in6 *) addr)->sin6_port);
 
-	ic_proxy_log(WARNING,
-				 "ic-proxy-addr: invalid address family %d for seg%d,dbid%d",
+	elog(WARNING,
+				 "ic-proxy: invalid address family %d for seg%d,dbid%d",
 				 addr->sockaddr.ss_family, addr->content, addr->dbid);
 	return -1;
 }

contrib/interconnect/proxy/ic_proxy_backend.c

@@ -110,7 +110,8 @@ ic_proxy_backend_on_close(uv_handle_t *handle)
 	backend = CONTAINER_OF((void *) handle, ICProxyBackend, pipe);
 	context = backend->pipe.loop->data;
 
-	ic_proxy_log(LOG, "backend %s: backend connection closed, begin to reconnect.",
+	elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG,
+		   "ic-proxy: backend %s: backend connection closed, begin to reconnect.",
 				 ic_proxy_key_to_str(&backend->key));
 
 	/* 
@@ -154,10 +155,13 @@ ic_proxy_backend_on_read_hello_ack(uv_stream_t *stream, ssize_t nread, const uv_
 	{
 		/* UV_EOF is expected */
 		if (nread == UV_EOF)
-			ic_proxy_log(LOG, "backend %s: received EOF while receiving HELLO ACK.",
-						 ic_proxy_key_to_str(&backend->key));
+		{
+			elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1,
+				   "ic-proxy: backend %s: received EOF while receiving HELLO ACK.",
+				   ic_proxy_key_to_str(&backend->key));
+		}
 		else
-			ic_proxy_log(WARNING, "backend %s: failed to recieve HELLO ACK: %s ",
+			elog(WARNING, "ic-proxy: backend %s: failed to recieve HELLO ACK: %s ",
 						 ic_proxy_key_to_str(&backend->key), uv_strerror(nread));
 
 		/* should close current pipe and try to reconnect */
@@ -234,14 +238,16 @@ ic_proxy_backend_on_sent_hello(uv_write_t *req, int status)
 
 	if (status < 0)
 	{
-		ic_proxy_log(LOG, "backend %s: backend failed to send HELLO: %s",
+		elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1,
+			   "ic-proxy: backend %s: backend failed to send HELLO: %s",
 					 ic_proxy_key_to_str(&backend->key), uv_strerror(status));
 		uv_close((uv_handle_t *) &backend->pipe, ic_proxy_backend_on_close);
 		return;
 	}
 
 	/* recieve hello ack */
-	ic_proxy_log(LOG, "backend %s: backend connected, receiving HELLO ACK",
+	elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1,
+		   "ic-proxy: backend %s: backend connected, receiving HELLO ACK",
 				 ic_proxy_key_to_str(&backend->key));
 
 	backend->offset = 0;
@@ -288,12 +294,13 @@ ic_proxy_backend_on_connected(uv_connect_t *conn, int status)
 	if (status < 0)
 	{
 		/* the proxy might just not get ready yet, retry later */
-		ic_proxy_log(LOG, "backend %s: backend failed to connect: %s",
+		elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1,
+			   "ic-proxy: backend %s: backend failed to connect: %s",
 					 ic_proxy_key_to_str(&backend->key), uv_strerror(status));
 
 		/* retry interval is 100ms and unit of interconnect_setup_timeout is second */
 		if (interconnect_setup_timeout * 1000 <=  backend->retryNum * CONNECT_TIMER_TIMEOUT)
-			ic_proxy_log(ERROR, "backend %s: Interconnect timeout: Unable to "
+			elog(ERROR, "ic-proxy: backend %s: Interconnect timeout: Unable to "
 						 "complete setup of connection within time limit %d seconds",
 						 ic_proxy_key_to_str(&backend->key), interconnect_setup_timeout);
 
@@ -304,7 +311,8 @@ ic_proxy_backend_on_connected(uv_connect_t *conn, int status)
 		return;
 	}
 
-	ic_proxy_log(LOG, "backend %s: backend connected, sending HELLO message.",
+	elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1,
+		   "ic-proxy: backend %s: backend connected, sending HELLO message.",
 				 ic_proxy_key_to_str(&backend->key));
 
 	/*