This is an automated email from the ASF dual-hosted git repository. avamingli pushed a commit to branch main in repository https://gitbox.apache.org/repos/asf/cloudberry.git
commit e8798016d344617430033c6239983d1efd6250d8 Author: Soumyadeep Chakraborty <[email protected]> AuthorDate: Mon Oct 3 10:10:26 2022 -0700 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 --- contrib/interconnect/proxy/ic_proxy.h | 12 -- contrib/interconnect/proxy/ic_proxy_addr.c | 25 ++-- contrib/interconnect/proxy/ic_proxy_backend.c | 26 ++-- contrib/interconnect/proxy/ic_proxy_client.c | 158 ++++++++++++++---------- contrib/interconnect/proxy/ic_proxy_iobuf.c | 15 ++- contrib/interconnect/proxy/ic_proxy_main.c | 89 +++++++------ contrib/interconnect/proxy/ic_proxy_peer.c | 103 +++++++++------ contrib/interconnect/proxy/ic_proxy_pkt_cache.c | 7 +- contrib/interconnect/proxy/ic_proxy_router.c | 25 ++-- 9 files changed, 272 insertions(+), 188 deletions(-) diff --git a/contrib/interconnect/proxy/ic_proxy.h b/contrib/interconnect/proxy/ic_proxy.h index e7da702caf..4935bee1a0 100644 --- a/contrib/interconnect/proxy/ic_proxy.h +++ b/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. * diff --git a/contrib/interconnect/proxy/ic_proxy_addr.c b/contrib/interconnect/proxy/ic_proxy_addr.c index 4e1ef28f7b..edc5dd4cfa 100644 --- a/contrib/interconnect/proxy/ic_proxy_addr.c +++ b/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; } diff --git a/contrib/interconnect/proxy/ic_proxy_backend.c b/contrib/interconnect/proxy/ic_proxy_backend.c index 75b8a61ede..91131eeff2 100644 --- a/contrib/interconnect/proxy/ic_proxy_backend.c +++ b/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)); /* diff --git a/contrib/interconnect/proxy/ic_proxy_client.c b/contrib/interconnect/proxy/ic_proxy_client.c index 017d85300e..b60c928139 100644 --- a/contrib/interconnect/proxy/ic_proxy_client.c +++ b/contrib/interconnect/proxy/ic_proxy_client.c @@ -201,8 +201,8 @@ ic_proxy_client_table_shutdown_by_dbid(uint16 dbid) ICProxyClientEntry *entry; HASH_SEQ_STATUS seq; - ic_proxy_log(LOG, - "ic-proxy-clients: shutting down all the clients by dbid %hu", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: shutting down all the clients by dbid %hu", dbid); hash_seq_init(&seq, ic_proxy_clients); @@ -241,7 +241,7 @@ ic_proxy_client_register(ICProxyClient *client) /* this should never happen */ if (client->state & IC_PROXY_CLIENT_STATE_REGISTERED) { - ic_proxy_log(WARNING, "%s: already registered", + elog(WARNING, "ic-proxy: %s: already registered", ic_proxy_client_get_name(client)); return; } @@ -256,8 +256,8 @@ ic_proxy_client_register(ICProxyClient *client) /* this should never happen, if it does, sth. serious is wrong */ if (placeholder == client) { - ic_proxy_log(ERROR, - "%s: unregistered client found in the client table", + elog(ERROR, + "ic-proxy: %s: unregistered client found in the client table", ic_proxy_client_get_name(client)); return; } @@ -271,14 +271,14 @@ ic_proxy_client_register(ICProxyClient *client) * * TODO: we believe the old one is shutting down, but what if not? */ - ic_proxy_log(WARNING, - "%s: delay the register as the previous client is still shutting down", + elog(WARNING, + "ic-proxy: %s: delay the register as the previous client is still shutting down", ic_proxy_client_get_name(client)); /* this should never happen, if it does, sth. serious is wrong */ if (placeholder->successor != NULL) - ic_proxy_log(ERROR, - "%s: the previous client already has a successor", + elog(ERROR, + "ic-proxy: %s: the previous client already has a successor", ic_proxy_client_get_name(client)); /* @@ -290,7 +290,8 @@ ic_proxy_client_register(ICProxyClient *client) } /* it's a placeholder, this happens if the pkts arrived before me */ - ic_proxy_log(LOG, "%s: replace my placeholder %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: replace my placeholder %s", ic_proxy_client_get_name(client), ic_proxy_client_get_name(placeholder)); @@ -300,7 +301,8 @@ ic_proxy_client_register(ICProxyClient *client) * it really happens, don't panic, nothing serious. */ if (placeholder->pkts == NIL) - ic_proxy_log(LOG, "%s: no cached pkts in the placeholder %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: no cached pkts in the placeholder %s", ic_proxy_client_get_name(client), ic_proxy_client_get_name(placeholder)); @@ -319,7 +321,8 @@ ic_proxy_client_register(ICProxyClient *client) * itself, so free it directly. */ ic_proxy_free(placeholder); - ic_proxy_log(LOG, "%s: freed my placeholder", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "%s: freed my placeholder", ic_proxy_client_get_name(client)); } } @@ -333,7 +336,8 @@ ic_proxy_client_register(ICProxyClient *client) /* clear the name so we could show the new name */ ic_proxy_client_clear_name(client); - ic_proxy_log(LOG, "%s: registered, %ld in total", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: registered, %ld in total", ic_proxy_client_get_name(client), hash_get_num_entries(ic_proxy_clients)); } @@ -358,7 +362,8 @@ ic_proxy_client_unregister(ICProxyClient *client) client->state &= ~IC_PROXY_CLIENT_STATE_REGISTERED; - ic_proxy_log(LOG, "%s: unregistered, %ld in total", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: unregistered, %ld in total", ic_proxy_client_get_name(client), hash_get_num_entries(ic_proxy_clients)); @@ -371,7 +376,8 @@ ic_proxy_client_unregister(ICProxyClient *client) if (client->pkts) { - ic_proxy_log(LOG, "%s: transfer %d unhandled pkts to my successor", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: transfer %d unhandled pkts to my successor", ic_proxy_client_get_name(client), list_length(client->pkts)); @@ -379,7 +385,8 @@ ic_proxy_client_unregister(ICProxyClient *client) client->pkts = NIL; } - ic_proxy_log(LOG, "%s: re-register my successor", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "%s: re-register my successor", ic_proxy_client_get_name(client)); /* the successor must have not registered */ @@ -396,7 +403,8 @@ ic_proxy_client_unregister(ICProxyClient *client) { ICProxyClient *placeholder; - ic_proxy_log(LOG, "%s: transfer %d unhandled pkts to my placeholder", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: transfer %d unhandled pkts to my placeholder", ic_proxy_client_get_name(client), list_length(client->pkts)); @@ -438,7 +446,8 @@ ic_proxy_client_blessed_lookup(uv_loop_t *loop, const ICProxyKey *key) client->key = *key; ic_proxy_client_register(client); - ic_proxy_log(LOG, "%s: registered as a placeholder", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: registered as a placeholder", ic_proxy_client_get_name(client)); } @@ -468,7 +477,8 @@ ic_proxy_client_on_c2p_data_pkt(void *opaque, const void *data, uint16 size) { ICProxyClient *client = opaque; - ic_proxy_log(LOG, "%s: received B2C PKT [%d bytes] from the backend", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: %s: received B2C PKT [%d bytes] from the backend", ic_proxy_client_get_name(client), size); /* increase the number of unack packets */ @@ -498,10 +508,11 @@ ic_proxy_client_on_c2p_data(uv_stream_t *stream, if (unlikely(nread < 0)) { if (nread != UV_EOF) - ic_proxy_log(WARNING, "%s: fail to receive c2p DATA: %s", + elog(WARNING, "ic-proxy: %s: fail to receive c2p DATA: %s", ic_proxy_client_get_name(client), uv_strerror(nread)); else - ic_proxy_log(LOG, "%s: received EOF while waiting for c2p DATA", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: received EOF while waiting for c2p DATA", ic_proxy_client_get_name(client)); if (buf->base) @@ -515,8 +526,8 @@ ic_proxy_client_on_c2p_data(uv_stream_t *stream, */ if (client->ibuf.len > 0) { - ic_proxy_log(LOG, - "%s: the ibuf still contains %d bytes," + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: the ibuf still contains %d bytes," " flush before shutting down", ic_proxy_client_get_name(client), client->ibuf.len); @@ -546,11 +557,12 @@ ic_proxy_client_on_c2p_data(uv_stream_t *stream, /* TODO: Will this really happen? */ if (client->state & IC_PROXY_CLIENT_STATE_PAUSED) - ic_proxy_log(ERROR, - "%s: paused already, but still received DATA[%zd bytes] from the backend, state is 0x%08x", + elog(ERROR, + "ic-proxy: %s: paused already, but still received DATA[%zd bytes] from the backend, state is 0x%08x", ic_proxy_client_get_name(client), nread, client->state); - ic_proxy_log(LOG, "%s: received DATA[%zd bytes] from the backend", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "%s: received DATA[%zd bytes] from the backend", ic_proxy_client_get_name(client), nread); /* @@ -575,7 +587,8 @@ ic_proxy_client_maybe_start_read_data(ICProxyClient *client) */ return; - ic_proxy_log(LOG, "%s: start receiving DATA", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: start receiving DATA", ic_proxy_client_get_name(client)); /* since now on, the client and backend communicate only via b2c packets */ @@ -596,8 +609,8 @@ ic_proxy_client_maybe_start_read_data(ICProxyClient *client) (IC_PROXY_CLIENT_STATE_C2P_SHUTTING | IC_PROXY_CLIENT_STATE_P2C_SHUTTING)) { - ic_proxy_log(WARNING, - "%s: state=0x%08x: unexpected shutting down in progress", + elog(WARNING, + "ic-proxy: %s: state=0x%08x: unexpected shutting down in progress", ic_proxy_client_get_name(client), client->state); return; } @@ -651,7 +664,7 @@ ic_proxy_client_on_hello_pkt(void *opaque, const void *data, uint16 size) if (!ic_proxy_pkt_is(pkt, IC_PROXY_MESSAGE_HELLO)) { - ic_proxy_log(WARNING, "%s: invalid %s", + elog(WARNING, "ic-proxy: %s: invalid %s", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); @@ -659,7 +672,8 @@ ic_proxy_client_on_hello_pkt(void *opaque, const void *data, uint16 size) return; } - ic_proxy_log(LOG, "%s: received %s from the backend", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "%s: received %s from the backend", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); client->state |= IC_PROXY_CLIENT_STATE_RECEIVED_HELLO; @@ -696,16 +710,17 @@ ic_proxy_client_on_hello_data(uv_stream_t *stream, if (unlikely(nread < 0)) { if (nread != UV_EOF) - ic_proxy_log(WARNING, "%s: fail to receive HELLO: %s", + elog(WARNING, "ic-proxy: %s: fail to receive HELLO: %s", ic_proxy_client_get_name(client), uv_strerror(nread)); else - ic_proxy_log(LOG, "%s: received EOF while waiting for HELLO", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: received EOF while waiting for HELLO", ic_proxy_client_get_name(client)); if (buf->base) ic_proxy_pkt_cache_free(buf->base); - ic_proxy_log(WARNING, "%s, TODO: fail to receive HELLO", + elog(WARNING, "ic-proxy: %s, failed to receive HELLO", ic_proxy_client_get_name(client)); /* * Pending data in a failed handshake is useless, @@ -755,7 +770,7 @@ ic_proxy_client_read_data(ICProxyClient *client) if (ret < 0) { - ic_proxy_log(WARNING, "%s: state=0x%08x: fail to start reading data: %s", + elog(WARNING, "ic-proxy: %s: state=0x%08x: fail to start reading data: %s", ic_proxy_client_get_name(client), client->state, uv_strerror(ret)); @@ -848,7 +863,8 @@ ic_proxy_client_new(uv_loop_t *loop, bool placeholder) static void ic_proxy_client_free(ICProxyClient *client) { - ic_proxy_log(LOG, "%s: freeing", ic_proxy_client_get_name(client)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: %s: freeing", ic_proxy_client_get_name(client)); /* * This should not happen, but in case it happens we want to leave a @@ -874,12 +890,13 @@ ic_proxy_client_on_close(uv_handle_t *handle) ICProxyClient *client = CONTAINER_OF((void *) handle, ICProxyClient, pipe); if (client->state & IC_PROXY_CLIENT_STATE_CLOSED) - ic_proxy_log(ERROR, "%s: double close", + elog(ERROR, "ic-proxy: %s: double close", ic_proxy_client_get_name(client)); client->state |= IC_PROXY_CLIENT_STATE_CLOSED; - ic_proxy_log(LOG, "%s: closed", ic_proxy_client_get_name(client)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, "%s: closed", + ic_proxy_client_get_name(client)); ic_proxy_client_free(client); } @@ -897,7 +914,8 @@ ic_proxy_client_close(ICProxyClient *client) ic_proxy_client_unregister(client); - ic_proxy_log(LOG, "%s: closing", ic_proxy_client_get_name(client)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: closing", ic_proxy_client_get_name(client)); uv_close((uv_handle_t *) &client->pipe, ic_proxy_client_on_close); } @@ -942,7 +960,8 @@ ic_proxy_client_on_sent_c2p_bye(void *opaque, const ICProxyPkt *pkt, int status) * lost. This can be safely ignored, we could just behave as it is * sent out. */ - ic_proxy_log(LOG, "%s: fail to shutdown c2p", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: fail to shutdown c2p", ic_proxy_client_get_name(client)); /* @@ -951,7 +970,8 @@ ic_proxy_client_on_sent_c2p_bye(void *opaque, const ICProxyPkt *pkt, int status) */ } - ic_proxy_log(LOG, "%s: shutted down c2p", ic_proxy_client_get_name(client)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutted down c2p", ic_proxy_client_get_name(client)); client->sending--; @@ -972,7 +992,8 @@ ic_proxy_client_shutdown_c2p(ICProxyClient *client) return; } - ic_proxy_log(LOG, "%s: shutting down c2p", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutting down c2p", ic_proxy_client_get_name(client)); client->state |= IC_PROXY_CLIENT_STATE_C2P_SHUTTING; @@ -999,7 +1020,8 @@ ic_proxy_client_shutdown_c2p(ICProxyClient *client) * and it has received the BYE and sent back a P2C BYE. */ - ic_proxy_log(LOG, "%s: shutted down c2p", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutted down c2p", ic_proxy_client_get_name(client)); client->state |= IC_PROXY_CLIENT_STATE_C2P_SHUTTED; @@ -1019,10 +1041,11 @@ ic_proxy_client_on_shutdown_p2c(uv_shutdown_t *req, int status) ic_proxy_free(req); if (status < 0) - ic_proxy_log(WARNING, "%s: fail to shutdown p2c: %s", + elog(WARNING, "ic-proxy: %s: fail to shutdown p2c: %s", ic_proxy_client_get_name(client), uv_strerror(status)); else - ic_proxy_log(LOG, "%s: shutted down p2c", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutted down p2c", ic_proxy_client_get_name(client)); client->state |= IC_PROXY_CLIENT_STATE_P2C_SHUTTED; @@ -1043,7 +1066,8 @@ ic_proxy_client_shutdown_p2c(ICProxyClient *client) return; } - ic_proxy_log(LOG, "%s: shutting down p2c", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutting down p2c", ic_proxy_client_get_name(client)); client->state |= IC_PROXY_CLIENT_STATE_P2C_SHUTTING; @@ -1107,7 +1131,8 @@ ic_proxy_client_on_p2c_message(ICProxyClient *client, const ICProxyPkt *pkt, { if (ic_proxy_pkt_is(pkt, IC_PROXY_MESSAGE_BYE)) { - ic_proxy_log(LOG, "%s: received %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: received %s", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); @@ -1117,7 +1142,8 @@ ic_proxy_client_on_p2c_message(ICProxyClient *client, const ICProxyPkt *pkt, } else if (ic_proxy_pkt_is(pkt, IC_PROXY_MESSAGE_DATA_ACK)) { - ic_proxy_log(LOG, "%s: received %s, with %d existing unack packets", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: received %s, with %d existing unack packets", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt), client->unackSendPkt); @@ -1127,7 +1153,7 @@ ic_proxy_client_on_p2c_message(ICProxyClient *client, const ICProxyPkt *pkt, #if 0 /* for debug purpose */ if (client->unackSendPkt < 0) - ic_proxy_log(WARNING, "%s: unexpected number of unack packets: %d", + elog(WARNING, "ic-proxy: %s: unexpected number of unack packets: %d", ic_proxy_client_get_name(client), client->unackSendPkt); #endif @@ -1136,7 +1162,7 @@ ic_proxy_client_on_p2c_message(ICProxyClient *client, const ICProxyPkt *pkt, } else { - ic_proxy_log(ERROR, "%s: unsupported message", + elog(ERROR, "ic-proxy: %s: unsupported message", ic_proxy_client_get_name(client)); } } @@ -1159,7 +1185,7 @@ ic_proxy_client_on_p2c_data(ICProxyClient *client, ICProxyPkt *pkt, #ifdef USE_ASSERT_CHECKING else if (!ic_proxy_pkt_is_to_client(pkt, &client->key)) { - ic_proxy_log(WARNING, "%s: the %s is not to me", + elog(WARNING, "ic-proxy: %s: the %s is not to me", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); /* TODO: callback? */ @@ -1170,7 +1196,8 @@ ic_proxy_client_on_p2c_data(ICProxyClient *client, ICProxyPkt *pkt, { if (ic_proxy_pkt_is_out_of_date(pkt, &client->key)) { - ic_proxy_log(LOG, "%s: drop out-of-date %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: drop out-of-date %s", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); /* TODO: callback? */ @@ -1180,7 +1207,8 @@ ic_proxy_client_on_p2c_data(ICProxyClient *client, ICProxyPkt *pkt, { Assert(ic_proxy_pkt_is_in_the_future(pkt, &client->key)); - ic_proxy_log(LOG, "%s: future %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: future %s", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); /* FIXME: also save the callback */ @@ -1230,7 +1258,8 @@ ic_proxy_client_cache_p2c_pkt(ICProxyClient *client, ICProxyPkt *pkt) client->pkts = lappend(client->pkts, pkt); - ic_proxy_log(LOG, "%s: cached a %s for future use, %d in the list", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: cached a %s for future use, %d in the list", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt), list_length(client->pkts)); } @@ -1247,8 +1276,8 @@ ic_proxy_client_cache_p2c_pkts(ICProxyClient *client, List *pkts) client->pkts = list_concat(client->pkts, pkts); - ic_proxy_log(LOG, - "%s: cached %d pkts for future use, %d in the list", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: cached %d pkts for future use, %d in the list", ic_proxy_client_get_name(client), list_length(pkts), list_length(client->pkts)); } @@ -1268,7 +1297,7 @@ ic_proxy_client_drop_p2c_cache(ICProxyClient *client) { ICProxyPkt *pkt = lfirst(cell); - ic_proxy_log(WARNING, "%s: unhandled cached %s, dropping it", + elog(WARNING, "ic-proxy: %s: unhandled cached %s, dropping it", ic_proxy_client_get_name(client), ic_proxy_pkt_to_str(pkt)); @@ -1300,7 +1329,8 @@ ic_proxy_client_handle_p2c_cache(ICProxyClient *client) if (client->pkts == NIL) return; - ic_proxy_log(LOG, "%s: trying to consume the %d cached pkts", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: trying to consume the %d cached pkts", ic_proxy_client_get_name(client), list_length(client->pkts)); /* @@ -1324,7 +1354,8 @@ ic_proxy_client_handle_p2c_cache(ICProxyClient *client) ic_proxy_client_on_p2c_data(client, pkt, NULL, NULL); } - ic_proxy_log(LOG, "%s: consumed %d cached pkts", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: consumed %d cached pkts", ic_proxy_client_get_name(client), count); } @@ -1334,7 +1365,8 @@ ic_proxy_client_handle_p2c_cache(ICProxyClient *client) static void ic_proxy_client_maybe_send_ack_message(ICProxyClient *client) { - ic_proxy_log(LOG, "%s: %d unconsumed packets to the backend", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: %d unconsumed packets to the backend", ic_proxy_client_get_name(client), client->unconsumed); /* @@ -1373,7 +1405,8 @@ ic_proxy_client_maybe_pause(ICProxyClient *client) client->state |= IC_PROXY_CLIENT_STATE_PAUSED; uv_read_stop((uv_stream_t *) &client->pipe); - ic_proxy_log(LOG, "%s: paused", ic_proxy_client_get_name(client)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: paused", ic_proxy_client_get_name(client)); } } @@ -1390,6 +1423,7 @@ ic_proxy_client_maybe_resume(ICProxyClient *client) client->state &= ~IC_PROXY_CLIENT_STATE_PAUSED; - ic_proxy_log(LOG, "%s: resumed", ic_proxy_client_get_name(client)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: resumed", ic_proxy_client_get_name(client)); } } diff --git a/contrib/interconnect/proxy/ic_proxy_iobuf.c b/contrib/interconnect/proxy/ic_proxy_iobuf.c index f155a584f6..6fd4b73f34 100644 --- a/contrib/interconnect/proxy/ic_proxy_iobuf.c +++ b/contrib/interconnect/proxy/ic_proxy_iobuf.c @@ -77,7 +77,7 @@ void ic_proxy_ibuf_clear(ICProxyIBuf *ibuf) { if (ibuf->len > 0) - ic_proxy_log(WARNING, "ic-proxy-ibuf: dropped %d bytes", ibuf->len); + elog(WARNING, "ic-proxy: dropped %d bytes", ibuf->len); ibuf->len = 0; } @@ -322,8 +322,8 @@ ic_proxy_obuf_push(ICProxyOBuf *obuf, void *opaque) { if (unlikely(obuf->buf == NULL)) - ic_proxy_log(ERROR, - "ic-proxy-obuf: the caller must init the header before pushing data"); + elog(ERROR, + "ic-proxy: the caller must init the header before pushing data"); /* * Need a flush when: @@ -333,8 +333,8 @@ ic_proxy_obuf_push(ICProxyOBuf *obuf, if (unlikely(size == 0 || size + obuf->len > IC_PROXY_MAX_PKT_SIZE)) { if (obuf->header_size + size > IC_PROXY_MAX_PKT_SIZE) - ic_proxy_log(ERROR, - "ic-proxy-obuf: no enough buffer to store the data:" + elog(ERROR, + "ic-proxy: not enough buffer to store the data:" " the data size is %d bytes," " but the buffer size is only %zd bytes," " including a %d bytes header", @@ -342,7 +342,10 @@ ic_proxy_obuf_push(ICProxyOBuf *obuf, /* TODO: should we flush if no data in the packet? */ if (obuf->len == obuf->header_size) - ic_proxy_log(LOG, "ic-proxy-obuf: no data to flush"); + { + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: no data to flush"); + } else { obuf->set_packet_size(obuf->buf, obuf->len); diff --git a/contrib/interconnect/proxy/ic_proxy_main.c b/contrib/interconnect/proxy/ic_proxy_main.c index ca77aabbf9..8e34f83253 100644 --- a/contrib/interconnect/proxy/ic_proxy_main.c +++ b/contrib/interconnect/proxy/ic_proxy_main.c @@ -54,7 +54,8 @@ static uv_pipe_t ic_proxy_postmaster_pipe; static void ic_proxy_server_peer_listener_on_closed(uv_handle_t *handle) { - ic_proxy_log(LOG, "ic-proxy-server: peer listener: closed"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: peer listener: closed"); /* A new peer listener will be created on the next timer callback */ ic_proxy_peer_listening = false; @@ -78,7 +79,7 @@ ic_proxy_server_on_new_peer(uv_stream_t *server, int status) if (status < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: new peer error: %s", + elog(WARNING, "ic-proxy: new peer error: %s", uv_strerror(status)); uv_close((uv_handle_t *) server, @@ -86,7 +87,8 @@ ic_proxy_server_on_new_peer(uv_stream_t *server, int status) return; } - ic_proxy_log(LOG, "ic-proxy-server: new peer to the server"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: new peer to the server"); peer = ic_proxy_peer_new(server->loop, IC_PROXY_INVALID_CONTENT, IC_PROXY_INVALID_DBID); @@ -94,7 +96,7 @@ ic_proxy_server_on_new_peer(uv_stream_t *server, int status) ret = uv_accept(server, (uv_stream_t *) &peer->tcp); if (ret < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: fail to accept new peer: %s", + elog(WARNING, "ic-proxy: fail to accept new peer: %s", uv_strerror(ret)); ic_proxy_peer_free(peer); return; @@ -116,7 +118,8 @@ ic_proxy_server_on_new_peer(uv_stream_t *server, int status) uv_ip4_name(peeraddr4, name, sizeof(name)); - ic_proxy_log(LOG, "ic-proxy-server: the new peer is from %s:%d", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: the new peer is from %s:%d", name, ntohs(peeraddr4->sin_port)); } else if (peeraddr.ss_family == AF_INET6) @@ -125,7 +128,8 @@ ic_proxy_server_on_new_peer(uv_stream_t *server, int status) uv_ip6_name(peeraddr6, name, sizeof(name)); - ic_proxy_log(LOG, "ic-proxy-server: the new peer is from %s:%d", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: the new peer is from %s:%d", name, ntohs(peeraddr6->sin6_port)); } } @@ -159,7 +163,7 @@ ic_proxy_server_peer_listener_init(uv_loop_t *loop) /* Cannot get my addr, maybe the setting is invalid */ return; -#if IC_PROXY_LOG_LEVEL <= LOG + if (gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE) { char name[HOST_NAME_MAX] = "unknown"; int port = 0; @@ -169,16 +173,15 @@ ic_proxy_server_peer_listener_init(uv_loop_t *loop) ret = ic_proxy_extract_sockaddr((struct sockaddr *) &addr->sockaddr, name, sizeof(name), &port, &family); if (ret == 0) - ic_proxy_log(LOG, - "ic-proxy-server: setting up peer listener on %s:%s (%s:%d family=%d)", + elog(LOG, + "ic-proxy: setting up peer listener on %s:%s (%s:%d family=%d)", addr->hostname, addr->service, name, port, family); else - ic_proxy_log(WARNING, - "ic-proxy-server: setting up peer listener on %s:%s (%s:%d family=%d) (fail to extract the address: %s)", + elog(WARNING, + "ic-proxy: setting up peer listener on %s:%s (%s:%d family=%d) (fail to extract the address: %s)", addr->hostname, addr->service, name, port, family, uv_strerror(ret)); } -#endif /* IC_PROXY_LOG_LEVEL <= LOG */ /* * It is important to set TCP_NODELAY, otherwise we will suffer from @@ -190,7 +193,7 @@ ic_proxy_server_peer_listener_init(uv_loop_t *loop) ret = uv_tcp_bind(listener, (struct sockaddr *) &addr->sockaddr, 0); if (ret < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: tcp: fail to bind: %s", + elog(WARNING, "ic-proxy: tcp: fail to bind: %s", uv_strerror(ret)); return; } @@ -199,13 +202,14 @@ ic_proxy_server_peer_listener_init(uv_loop_t *loop) IC_PROXY_BACKLOG, ic_proxy_server_on_new_peer); if (ret < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: tcp: fail to listen: %s", + elog(WARNING, "ic-proxy: tcp: fail to listen: %s", uv_strerror(ret)); return; } uv_fileno((uv_handle_t *) listener, &fd); - ic_proxy_log(LOG, "ic-proxy-server: tcp: listening on socket %d", fd); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: tcp: listening on socket %d", fd); ic_proxy_peer_listening = true; } @@ -228,7 +232,7 @@ ic_proxy_server_peer_listener_reinit(uv_loop_t *loop) * keep the ic_proxy_peer_listening as true during the process to * prevent double connect. */ - ic_proxy_log(LOG, "ic-proxy-server: closing the legacy peer listener"); + elog(LOG, "ic-proxy: closing the legacy peer listener"); /* Only recreate a new listener if an address is assigned to us */ ic_proxy_peer_relistening = !!myaddr; @@ -250,7 +254,8 @@ ic_proxy_server_peer_listener_reinit(uv_loop_t *loop) static void ic_proxy_server_client_listener_on_closed(uv_handle_t *handle) { - ic_proxy_log(LOG, "ic-proxy-server: client listener: closed"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: client listener: closed"); /* A new client listener will be created on the next timer callback */ ic_proxy_client_listening = false; @@ -267,7 +272,7 @@ ic_proxy_server_on_new_client(uv_stream_t *server, int status) if (status < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: new client error: %s", + elog(WARNING, "ic-proxy: new client error: %s", uv_strerror(status)); uv_close((uv_handle_t *) server, @@ -275,14 +280,15 @@ ic_proxy_server_on_new_client(uv_stream_t *server, int status) return; } - ic_proxy_log(LOG, "ic-proxy-server: new client to the server"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: new client to the server"); client = ic_proxy_client_new(server->loop, false); ret = uv_accept(server, ic_proxy_client_get_stream(client)); if (ret < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: fail to accept new client: %s", + elog(WARNING, "ic-proxy: fail to accept new client: %s", uv_strerror(ret)); return; } @@ -310,17 +316,19 @@ ic_proxy_server_client_listener_init(uv_loop_t *loop) ic_proxy_build_server_sock_path(path, sizeof(path)); /* FIXME: do not unlink here */ - ic_proxy_log(LOG, "unlink(%s) ...", path); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: unlink(%s) ...", path); unlink(path); - ic_proxy_log(LOG, "ic-proxy-server: setting up client listener on address %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: setting up client listener on address %s", path); ret = uv_pipe_init(loop, listener, false); if (ret < 0) { - ic_proxy_log(WARNING, - "ic-proxy-server: fail to init a client listener: %s", + elog(WARNING, + "ic-proxy: fail to init a client listener: %s", uv_strerror(ret)); return; } @@ -328,7 +336,7 @@ ic_proxy_server_client_listener_init(uv_loop_t *loop) ret = uv_pipe_bind(listener, path); if (ret < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: pipe: fail to bind(%s): %s", + elog(WARNING, "ic-proxy: pipe: fail to bind(%s): %s", path, uv_strerror(ret)); return; } @@ -337,13 +345,14 @@ ic_proxy_server_client_listener_init(uv_loop_t *loop) IC_PROXY_BACKLOG, ic_proxy_server_on_new_client); if (ret < 0) { - ic_proxy_log(WARNING, "ic-proxy-server: pipe: fail to listen on path %s: %s", + elog(WARNING, "ic-proxy: pipe: fail to listen on path %s: %s", path, uv_strerror(ret)); return; } uv_fileno((uv_handle_t *) listener, &fd); - ic_proxy_log(LOG, "ic-proxy-server: pipe: listening on socket %d", fd); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: pipe: listening on socket %d", fd); /* * Dump the inode of the domain socket file, this helps us to know that the @@ -354,7 +363,8 @@ ic_proxy_server_client_listener_init(uv_loop_t *loop) struct stat st; stat(path, &st); - ic_proxy_log(LOG, "ic-proxy-server: dev=%lu, inode=%lu, path=%s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: dev=%lu, inode=%lu, path=%s", st.st_dev, st.st_ino, path); } @@ -471,7 +481,8 @@ ic_proxy_server_on_timer(uv_timer_t *timer) static void ic_proxy_server_on_signal(uv_signal_t *handle, int signum) { - ic_proxy_log(WARNING, "ic-proxy-server: received signal %d", signum); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_TERSE, + LOG, "ic-proxy: received signal %d", signum); if (signum == SIGHUP) { @@ -504,9 +515,9 @@ ic_proxy_server_on_read_postmaster_pipe(uv_stream_t *stream, ssize_t nread, cons if (nread == UV_EOF) proc_exit(1); else if (nread < 0) - ic_proxy_log(FATAL, "read on postmaster death monitoring pipe failed: %s", uv_strerror(nread)); + elog(FATAL, "ic-proxy: read on postmaster death monitoring pipe failed: %s", uv_strerror(nread)); else if (nread > 0) - ic_proxy_log(FATAL, "unexpected data in postmaster death monitoring pipe with length: %ld", nread); + elog(FATAL, "ic-proxy: unexpected data in postmaster death monitoring pipe with length: %ld", nread); } /* @@ -517,7 +528,8 @@ ic_proxy_server_main(void) { char path[MAXPGPATH]; - ic_proxy_log(LOG, "ic-proxy-server: setting up"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_TERSE, + LOG, "ic-proxy: server setting up"); ic_proxy_pkt_cache_init(IC_PROXY_MAX_PKT_SIZE); @@ -557,7 +569,8 @@ ic_proxy_server_main(void) uv_read_start((uv_stream_t *)&ic_proxy_postmaster_pipe, ic_proxy_pkt_cache_alloc_buffer, ic_proxy_server_on_read_postmaster_pipe); - ic_proxy_log(LOG, "ic-proxy-server: running"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_TERSE, LOG, + "ic-proxy: server running"); /* We're now ready to receive signals */ BackgroundWorkerUnblockSignals(); @@ -570,7 +583,7 @@ ic_proxy_server_main(void) uv_run(&ic_proxy_server_loop, UV_RUN_DEFAULT); uv_loop_close(&ic_proxy_server_loop); - ic_proxy_log(LOG, "ic-proxy-server: closing"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_TERSE, LOG, "ic-proxy: server closing"); ic_proxy_client_table_uninit(); ic_proxy_peer_table_uninit(); @@ -578,13 +591,14 @@ ic_proxy_server_main(void) ic_proxy_build_server_sock_path(path, sizeof(path)); #if 0 - ic_proxy_log(LOG, "unlink(%s) ...", path); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG5, LOG, "unlink(%s) ...", path); unlink(path); #endif ic_proxy_pkt_cache_uninit(); - ic_proxy_log(LOG, "ic-proxy-server: closed with code %d", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_TERSE, LOG, + "ic-proxy: server closed with code %d", ic_proxy_server_exit_code); return ic_proxy_server_exit_code; @@ -593,7 +607,8 @@ ic_proxy_server_main(void) void ic_proxy_server_quit(uv_loop_t *loop, bool relaunch) { - ic_proxy_log(LOG, "ic-proxy-server: quiting"); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_TERSE, LOG, + "ic-proxy: server quiting"); if (relaunch) /* return non-zero value so we are restarted by the postmaster */ diff --git a/contrib/interconnect/proxy/ic_proxy_peer.c b/contrib/interconnect/proxy/ic_proxy_peer.c index 9e5f46cd07..b0c5a990b1 100644 --- a/contrib/interconnect/proxy/ic_proxy_peer.c +++ b/contrib/interconnect/proxy/ic_proxy_peer.c @@ -160,7 +160,8 @@ ic_proxy_peer_unregister(ICProxyPeer *peer) { /* keep the peer as a placeholder */ - ic_proxy_log(LOG, "%s: unregistered", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy %s: unregistered", peer->name); /* reset the state */ peer->state = 0; @@ -204,7 +205,7 @@ ic_proxy_peer_register(ICProxyPeer *peer) * This is not actually a placeholder, but a legacy peer, this * happens due to network problem, etc.. */ - ic_proxy_log(WARNING, "%s(state=0x%08x): found a legacy peer %s(state=0x%08x)", + elog(WARNING, "ic-proxy: %s(state=0x%08x): found a legacy peer %s(state=0x%08x)", peer->name, peer->state, placeholder->name, placeholder->state); @@ -216,12 +217,13 @@ ic_proxy_peer_register(ICProxyPeer *peer) else { /* This is an actual placeholder */ - ic_proxy_log(LOG, "%s(state=0x%08x): found my placeholder %s(state=0x%08x)", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s(state=0x%08x): found my placeholder %s(state=0x%08x)", peer->name, peer->state, placeholder->name, placeholder->state); if (placeholder->ibuf.len > 0) - ic_proxy_log(WARNING, "%s(state=0x%08x): my placeholder %s(state=0x%08x) has %d bytes in ibuf", + elog(WARNING, "ic-proxy: %s(state=0x%08x): my placeholder %s(state=0x%08x) has %d bytes in ibuf", peer->name, peer->state, placeholder->name, placeholder->state, placeholder->ibuf.len); @@ -239,7 +241,8 @@ ic_proxy_peer_register(ICProxyPeer *peer) ic_proxy_peers[peer->dbid] = peer; - ic_proxy_log(LOG, "%s: registered", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: registered", peer->name); } /* @@ -284,11 +287,12 @@ ic_proxy_peer_on_data_pkt(void *opaque, const void *data, uint16 size) const ICProxyPkt *pkt = data; ICProxyPeer *peer = opaque; - ic_proxy_log(LOG, "%s: received %s", peer->name, ic_proxy_pkt_to_str(pkt)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: %s: received %s", peer->name, ic_proxy_pkt_to_str(pkt)); if (!(peer->state & IC_PROXY_PEER_STATE_READY_FOR_DATA)) { - ic_proxy_log(WARNING, "%s: not ready to receive DATA yet: %s", + elog(WARNING, "ic-proxy: %s: not ready to receive DATA yet: %s", peer->name, ic_proxy_pkt_to_str(pkt)); return; } @@ -307,10 +311,11 @@ ic_proxy_peer_on_data(uv_stream_t *stream, ssize_t nread, const uv_buf_t *buf) if (unlikely(nread < 0)) { if (nread != UV_EOF) - ic_proxy_log(WARNING, "%s: fail to receive DATA: %s", + elog(WARNING, "ic-proxy: %s: fail to receive DATA: %s", peer->name, uv_strerror(nread)); else - ic_proxy_log(LOG, "%s: received EOF while waiting for DATA", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: received EOF while waiting for DATA", peer->name); if (buf->base) @@ -369,13 +374,14 @@ ic_proxy_peer_free(ICProxyPeer *peer) { ListCell *cell; - ic_proxy_log(LOG, "%s: freeing", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: %s: freeing", peer->name); foreach(cell, peer->reqs) { ICProxyPkt *pkt = lfirst(cell); - ic_proxy_log(WARNING, "%s: unhandled outgoing %s, dropping it", + elog(WARNING, "ic-proxy: %s: unhandled outgoing %s, dropping it", peer->name, ic_proxy_pkt_to_str(pkt)); ic_proxy_pkt_cache_free(pkt); @@ -402,7 +408,8 @@ ic_proxy_peer_on_close(uv_handle_t *handle) { ICProxyPeer *peer = CONTAINER_OF((void *) handle, ICProxyPeer, tcp); - ic_proxy_log(LOG, "%s: closed", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "%s: closed", peer->name); /* reset the state */ peer->state = 0; @@ -424,7 +431,8 @@ ic_proxy_peer_close(ICProxyPeer *peer) if (peer->state & IC_PROXY_PEER_STATE_CLOSING) return; - ic_proxy_log(LOG, "%s: closing", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: closing", peer->name); peer->state |= IC_PROXY_PEER_STATE_CLOSING; @@ -442,10 +450,11 @@ ic_proxy_peer_on_shutdown(uv_shutdown_t *req, int status) ic_proxy_free(req); if (status < 0) - ic_proxy_log(WARNING, "%s: fail to shutdown: %s", + elog(WARNING, "ic-proxy: %s: fail to shutdown: %s", peer->name, uv_strerror(status)); - ic_proxy_log(LOG, "%s: shutted down", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutted down", peer->name); peer->state |= IC_PROXY_PEER_STATE_SHUTTED; @@ -463,7 +472,8 @@ ic_proxy_peer_shutdown(ICProxyPeer *peer) if (peer->state & IC_PROXY_PEER_STATE_SHUTTING) return; - ic_proxy_log(LOG, "%s: shutting down", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: shutting down", peer->name); peer->state |= IC_PROXY_PEER_STATE_SHUTTING; @@ -491,7 +501,8 @@ ic_proxy_peer_on_sent_hello_ack(void *opaque, const ICProxyPkt *pkt, int status) peer->state |= IC_PROXY_PEER_STATE_SENT_HELLO_ACK; - ic_proxy_log(LOG, "%s: start receiving DATA", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: start receiving DATA", peer->name); /* it's unlikely that the ibuf is non-empty, but clear it for sure */ ic_proxy_ibuf_clear(&peer->ibuf); @@ -536,7 +547,8 @@ ic_proxy_peer_on_hello_pkt(void *opaque, const void *data, uint16 size) */ ic_proxy_peer_register(peer); - ic_proxy_log(LOG, "%s: received %s, sending HELLO ACK", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: received %s, sending HELLO ACK", peer->name, ic_proxy_pkt_to_str(pkt)); /* @@ -566,10 +578,11 @@ ic_proxy_peer_on_hello_data(uv_stream_t *stream, if (unlikely(nread < 0)) { if (nread != UV_EOF) - ic_proxy_log(WARNING, "%s: fail to receive HELLO: %s", + elog(WARNING, "ic-proxy: %s: fail to receive HELLO: %s", peer->name, uv_strerror(nread)); else - ic_proxy_log(LOG, "%s: received EOF while waiting for HELLO", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: received EOF while waiting for HELLO", peer->name); if (buf->base) @@ -601,7 +614,8 @@ ic_proxy_peer_read_hello(ICProxyPeer *peer) if (peer->state & IC_PROXY_PEER_STATE_RECEIVING_HELLO) return; - ic_proxy_log(LOG, "%s: waiting for HELLO", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: waiting for HELLO", peer->name); peer->state |= IC_PROXY_PEER_STATE_RECEIVING_HELLO; @@ -619,7 +633,7 @@ ic_proxy_peer_on_hello_ack_pkt(void *opaque, const void *data, uint16 size) ICProxyPeer *peer = opaque; if (size < sizeof(*pkt) || size != pkt->len) - ic_proxy_log(ERROR, "%s: received incomplete HELLO ACK: size = %d", + elog(ERROR, "ic-proxy: %s: received incomplete HELLO ACK: size = %d", peer->name, size); if (peer->state & IC_PROXY_PEER_STATE_RECEIVED_HELLO_ACK) @@ -632,7 +646,7 @@ ic_proxy_peer_on_hello_ack_pkt(void *opaque, const void *data, uint16 size) * TODO: as we can't draw a clear line between handshake and data, it * would be better to merge on_hello* and on_data into one. */ - ic_proxy_log(WARNING, "%s: early DATA: %s", + elog(WARNING, "ic-proxy: %s: early DATA: %s", peer->name, ic_proxy_pkt_to_str(pkt)); ic_proxy_peer_on_data_pkt(opaque, data, size); @@ -640,17 +654,18 @@ ic_proxy_peer_on_hello_ack_pkt(void *opaque, const void *data, uint16 size) } if (!ic_proxy_pkt_is(pkt, IC_PROXY_MESSAGE_PEER_HELLO_ACK)) - ic_proxy_log(ERROR, "%s: received invalid HELLO ACK: %s", + elog(ERROR, "ic-proxy: %s: received invalid HELLO ACK: %s", peer->name, ic_proxy_pkt_to_str(pkt)); if (pkt->dstDbid != peer->dbid) - ic_proxy_log(ERROR, "%s: received invalid HELLO ACK: %s", + elog(ERROR, "ic-proxy: %s: received invalid HELLO ACK: %s", peer->name, ic_proxy_pkt_to_str(pkt)); /* we only expect one hello ack message */ uv_read_stop((uv_stream_t *) &peer->tcp); - ic_proxy_log(LOG, "%s: received %s", peer->name, ic_proxy_pkt_to_str(pkt)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: received %s", peer->name, ic_proxy_pkt_to_str(pkt)); peer->state |= IC_PROXY_PEER_STATE_RECEIVED_HELLO_ACK; @@ -663,7 +678,8 @@ ic_proxy_peer_on_hello_ack_pkt(void *opaque, const void *data, uint16 size) */ ic_proxy_peer_handle_out_cache(peer); - ic_proxy_log(LOG, "%s: start receiving DATA", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: start receiving DATA", peer->name); /* now it's time to receive the normal data */ uv_read_start((uv_stream_t *) &peer->tcp, @@ -682,10 +698,11 @@ ic_proxy_peer_on_hello_ack_data(uv_stream_t *stream, if (unlikely(nread < 0)) { if (nread != UV_EOF) - ic_proxy_log(WARNING, "%s: fail to recv HELLO ACK: %s", + elog(WARNING, "%s: fail to recv HELLO ACK: %s", peer->name, uv_strerror(nread)); else - ic_proxy_log(LOG, "%s: received EOF while waiting for HELLO ACK", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: received EOF while waiting for HELLO ACK", peer->name); if (buf->base) @@ -722,7 +739,8 @@ ic_proxy_peer_on_sent_hello(void *opaque, const ICProxyPkt *pkt, int status) return; } - ic_proxy_log(LOG, "%s: waiting for HELLO ACK", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: waiting for HELLO ACK", peer->name); peer->state |= IC_PROXY_PEER_STATE_SENT_HELLO; @@ -748,13 +766,15 @@ ic_proxy_peer_on_connected(uv_connect_t *conn, int status) if (status < 0) { /* the peer might just not get ready yet, retry later */ - ic_proxy_log(LOG, "%s: fail to connect: %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_VERBOSE, LOG, + "ic-proxy: %s: fail to connect: %s", peer->name, uv_strerror(status)); ic_proxy_peer_close(peer); return; } - ic_proxy_log(LOG, "%s: connected, sending HELLO", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG1, + "ic-proxy: %s: connected, sending HELLO", peer->name); peer->state |= IC_PROXY_PEER_STATE_CONNECTED; @@ -800,7 +820,8 @@ ic_proxy_peer_connect(ICProxyPeer *peer, struct sockaddr_in *dest) peer->state |= IC_PROXY_PEER_STATE_CONNECTING; uv_ip4_name(dest, name, sizeof(name)); - ic_proxy_log(LOG, "%s: connecting to %s:%d", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: connecting to %s:%d", peer->name, name, ntohs(dest->sin_port)); /* reinit the tcp handle */ @@ -830,7 +851,8 @@ ic_proxy_peer_disconnect(ICProxyPeer *peer) if (!(peer->state & IC_PROXY_PEER_STATE_CONNECTING)) return; - ic_proxy_log(LOG, "%s: disconnecting", peer->name); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: disconnecting", peer->name); ic_proxy_peer_shutdown(peer); } @@ -845,7 +867,8 @@ ic_proxy_peer_route_data(ICProxyPeer *peer, ICProxyPkt *pkt, { ICProxyDelay *delay; - ic_proxy_log(LOG, "%s: caching outgoing %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: caching outgoing %s", peer->name, ic_proxy_pkt_to_str(pkt)); delay = ic_proxy_peer_build_delay(peer, pkt, callback, opaque); @@ -871,8 +894,8 @@ ic_proxy_peer_send_message(ICProxyPeer *peer, ICProxyMessageType mtype, ICProxyPkt *pkt; if (!(peer->state & IC_PROXY_PEER_STATE_READY_FOR_MESSAGE)) - ic_proxy_log(ERROR, - "%s: not ready to send or receive messages", + elog(ERROR, + "ic-proxy: %s: not ready to send or receive messages", peer->name); pkt = ic_proxy_message_new(mtype, key); @@ -896,7 +919,8 @@ ic_proxy_peer_handle_out_cache(ICProxyPeer *peer) if (peer->reqs == NIL) return; - ic_proxy_log(LOG, "%s: trying to consume the %d cached outgoing pkts", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "ic-proxy: %s: trying to consume the %d cached outgoing pkts", peer->name, list_length(peer->reqs)); /* First detach all the pkts */ @@ -915,7 +939,8 @@ ic_proxy_peer_handle_out_cache(ICProxyPeer *peer) ic_proxy_free(delay); } - ic_proxy_log(LOG, "%s: consumed %d cached pkts", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG3, + "%s: consumed %d cached pkts", peer->name, list_length(reqs) - list_length(peer->reqs)); /* diff --git a/contrib/interconnect/proxy/ic_proxy_pkt_cache.c b/contrib/interconnect/proxy/ic_proxy_pkt_cache.c index 4beceb409b..bb68e90d35 100644 --- a/contrib/interconnect/proxy/ic_proxy_pkt_cache.c +++ b/contrib/interconnect/proxy/ic_proxy_pkt_cache.c @@ -26,7 +26,6 @@ *------------------------------------------------------------------------- */ -#define IC_PROXY_LOG_LEVEL WARNING #include "ic_proxy.h" #include "ic_proxy_pkt_cache.h" @@ -113,7 +112,8 @@ ic_proxy_pkt_cache_alloc(size_t *pkt_size) memset(cpkt, 0, ic_proxy_pkt_cache.pkt_size); #endif - ic_proxy_log(LOG, "pkt-cache: allocated, %d free, %d total", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: pkt-cache: allocated, %d free, %d total", ic_proxy_pkt_cache.n_free, ic_proxy_pkt_cache.n_total); return cpkt; } @@ -159,7 +159,8 @@ ic_proxy_pkt_cache_free(void *pkt) ic_proxy_pkt_cache.freelist = cpkt; ic_proxy_pkt_cache.n_free++; - ic_proxy_log(LOG, "pkt-cache: recycled, %d free, %d total", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: pkt-cache: recycled, %d free, %d total", ic_proxy_pkt_cache.n_free, ic_proxy_pkt_cache.n_total); } } diff --git a/contrib/interconnect/proxy/ic_proxy_router.c b/contrib/interconnect/proxy/ic_proxy_router.c index 51c962a54e..77b5f36bb6 100644 --- a/contrib/interconnect/proxy/ic_proxy_router.c +++ b/contrib/interconnect/proxy/ic_proxy_router.c @@ -104,7 +104,8 @@ ic_proxy_router_loopback_on_check(uv_check_t *handle) ic_proxy_key_from_p2c_pkt(&key, delay->pkt); client = ic_proxy_client_blessed_lookup(handle->loop, &key); - ic_proxy_log(LOG, "ic-proxy-router: looped back %s to %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: looped back %s to %s", ic_proxy_pkt_to_str(delay->pkt), ic_proxy_client_get_name(client)); @@ -131,7 +132,8 @@ ic_proxy_router_loopback_push(ICProxyPkt *pkt, { ICProxyDelay *delay; - ic_proxy_log(LOG, "ic-proxy-router: looping back %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: looping back %s", ic_proxy_pkt_to_str(pkt)); /* @@ -221,7 +223,8 @@ ic_proxy_router_route(uv_loop_t *loop, ICProxyPkt *pkt, ic_proxy_key_from_p2c_pkt(&key, pkt); client = ic_proxy_client_blessed_lookup(loop, &key); - ic_proxy_log(LOG, "ic-proxy-router: routing %s to %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: routing %s to %s", ic_proxy_pkt_to_str(pkt), ic_proxy_client_get_name(client)); @@ -234,7 +237,8 @@ ic_proxy_router_route(uv_loop_t *loop, ICProxyPkt *pkt, peer = ic_proxy_peer_blessed_lookup(loop, pkt->dstContentId, pkt->dstDbid); - ic_proxy_log(LOG, "ic-proxy-router: routing %s to %s", + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: routing %s to %s", ic_proxy_pkt_to_str(pkt), peer->name); ic_proxy_peer_route_data(peer, pkt, callback, opaque); @@ -251,11 +255,17 @@ ic_proxy_router_on_write(uv_write_t *req, int status) ICProxyPkt *pkt = req->data; if (status < 0) - ic_proxy_log(LOG, "ic-proxy-router: fail to send %s: %s", + { + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: fail to send %s: %s", ic_proxy_pkt_to_str(pkt), uv_strerror(status)); + } else - ic_proxy_log(LOG, "ic-proxy-router: sent %s", + { + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: sent %s", ic_proxy_pkt_to_str(pkt)); + } if (wreq->callback) wreq->callback(wreq->opaque, pkt, status); @@ -289,7 +299,8 @@ ic_proxy_router_write(uv_stream_t *stream, ICProxyPkt *pkt, int32 offset, ICProxyWriteReq *wreq; uv_buf_t wbuf; - ic_proxy_log(LOG, "ic-proxy-router: sending %s", ic_proxy_pkt_to_str(pkt)); + elogif(gp_log_interconnect >= GPVARS_VERBOSITY_DEBUG, DEBUG5, + "ic-proxy: router: sending %s", ic_proxy_pkt_to_str(pkt)); wreq = ic_proxy_new(ICProxyWriteReq); --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
