Merge pull request #1338 from jtattermusch/windows_less_verbose

Less verbose logs on windows

src/core/iomgr/iocp_windows.c

@@ -78,7 +78,6 @@ static void do_iocp_work() {
   if (overlapped == &g_iocp_custom_overlap) {
     if (completion_key == (ULONG_PTR) &g_iocp_kick_token) {
       /* We were awoken from a kick. */
-      gpr_log(GPR_DEBUG, "do_iocp_work - got a kick");
       return;
     }
     gpr_log(GPR_ERROR, "Unknown custom completion key.");
@@ -87,10 +86,8 @@ static void do_iocp_work() {
 
   socket = (grpc_winsocket*) completion_key;
   if (overlapped == &socket->write_info.overlapped) {
-    gpr_log(GPR_DEBUG, "do_iocp_work - got write packet");
     info = &socket->write_info;
   } else if (overlapped == &socket->read_info.overlapped) {
-    gpr_log(GPR_DEBUG, "do_iocp_work - got read packet");
     info = &socket->read_info;
   } else {
     gpr_log(GPR_ERROR, "Unknown IOCP operation");
@@ -98,8 +95,6 @@ static void do_iocp_work() {
   }
   success = WSAGetOverlappedResult(socket->socket, &info->overlapped, &bytes,
                                    FALSE, &flags);
-  gpr_log(GPR_DEBUG, "bytes: %u, flags: %u - op %s %s", bytes, flags,
-          success ? "succeeded" : "failed", socket->orphan ? "orphan" : "");
   if (socket->orphan) {
     grpc_winsocket_destroy(socket);
     gpr_atm_full_fetch_add(&g_orphans, -1);
@@ -189,11 +184,9 @@ static void socket_notify_on_iocp(grpc_winsocket *socket,
   if (info->has_pending_iocp) {
     run_now = 1;
     info->has_pending_iocp = 0;
-    gpr_log(GPR_DEBUG, "socket_notify_on_iocp - runs now");
   } else {
     info->cb = cb;
     info->opaque = opaque;
-    gpr_log(GPR_DEBUG, "socket_notify_on_iocp - queued");
   }
   gpr_mu_unlock(&socket->state_mu);
   if (run_now) cb(opaque, 1);
@@ -201,13 +194,11 @@ static void socket_notify_on_iocp(grpc_winsocket *socket,
 
 void grpc_socket_notify_on_write(grpc_winsocket *socket,
                                  void(*cb)(void *, int), void *opaque) {
-  gpr_log(GPR_DEBUG, "grpc_socket_notify_on_write");
   socket_notify_on_iocp(socket, cb, opaque, &socket->write_info);
 }
 
 void grpc_socket_notify_on_read(grpc_winsocket *socket,
                                 void(*cb)(void *, int), void *opaque) {
-  gpr_log(GPR_DEBUG, "grpc_socket_notify_on_read");
   socket_notify_on_iocp(socket, cb, opaque, &socket->read_info);
 }
 

src/core/iomgr/resolve_address_windows.c

@@ -107,18 +107,14 @@ grpc_resolved_addresses *grpc_blocking_resolve_address(
     i++;
   }
 
-  /* Temporary logging, to help identify flakiness in dualstack_socket_test. */
   {
     const gpr_timespec delay = gpr_time_sub(gpr_now(), start_time);
     const int delay_ms =
         delay.tv_sec * GPR_MS_PER_SEC + delay.tv_nsec / GPR_NS_PER_MS;
-    gpr_log(GPR_INFO, "logspam: getaddrinfo(%s, %s) resolved %d addrs in %dms:",
-            host, port, addrs->naddrs, delay_ms);
     for (i = 0; i < addrs->naddrs; i++) {
       char *buf;
       grpc_sockaddr_to_string(&buf, (struct sockaddr *)&addrs->addrs[i].addr,
                               0);
-      gpr_log(GPR_INFO, "logspam:   [%d] %s", i, buf);
       gpr_free(buf);
     }
   }

src/core/iomgr/socket_windows.c

@@ -46,7 +46,6 @@
 
 grpc_winsocket *grpc_winsocket_create(SOCKET socket) {
   grpc_winsocket *r = gpr_malloc(sizeof(grpc_winsocket));
-  gpr_log(GPR_DEBUG, "grpc_winsocket_create");
   memset(r, 0, sizeof(grpc_winsocket));
   r->socket = socket;
   gpr_mu_init(&r->state_mu);
@@ -61,13 +60,11 @@ static void shutdown_op(grpc_winsocket_callback_info *info) {
 }
 
 void grpc_winsocket_shutdown(grpc_winsocket *socket) {
-  gpr_log(GPR_DEBUG, "grpc_winsocket_shutdown");
   shutdown_op(&socket->read_info);
   shutdown_op(&socket->write_info);
 }
 
 void grpc_winsocket_orphan(grpc_winsocket *socket) {
-  gpr_log(GPR_DEBUG, "grpc_winsocket_orphan");
   grpc_iocp_socket_orphan(socket);
   socket->orphan = 1;
   grpc_iomgr_unref();

src/core/iomgr/tcp_client_windows.c

@@ -102,7 +102,6 @@ static void on_connect(void *acp, int success) {
       gpr_free(utf8_message);
       goto finish;
     } else {
-      gpr_log(GPR_DEBUG, "on_connect: connection established");
       ep = grpc_tcp_create(ac->socket);
       goto finish;
     }
@@ -179,9 +178,7 @@ void grpc_tcp_client_connect(void(*cb)(void *arg, grpc_endpoint *tcp),
   info = &socket->write_info;
   success = ConnectEx(sock, addr, addr_len, NULL, 0, NULL, &info->overlapped);
 
-  if (success) {
-    gpr_log(GPR_DEBUG, "connected immediately - but we still go to sleep");
-  } else {
+  if (!success) {
     int error = WSAGetLastError();
     if (error != ERROR_IO_PENDING) {
       message = "ConnectEx failed: %s";
@@ -189,7 +186,6 @@ void grpc_tcp_client_connect(void(*cb)(void *arg, grpc_endpoint *tcp),
     }
   }
 
-  gpr_log(GPR_DEBUG, "grpc_tcp_client_connect: connection pending");
   ac = gpr_malloc(sizeof(async_connect));
   ac->cb = cb;
   ac->cb_arg = arg;

src/core/iomgr/tcp_server_windows.c

@@ -195,9 +195,7 @@ static void start_accept(server_port *port) {
                            addrlen, addrlen, &bytes_received,
                            &port->socket->read_info.overlapped);
 
-  if (success) {
-    gpr_log(GPR_DEBUG, "accepted immediately - but we still go to sleep");
-  } else {
+  if (!success) {
     int error = WSAGetLastError();
     if (error != ERROR_IO_PENDING) {
       message = "AcceptEx failed: %s";
@@ -234,11 +232,9 @@ static void on_accept(void *arg, int success) {
       gpr_free(utf8_message);
       closesocket(sock);
     } else {
-      gpr_log(GPR_DEBUG, "on_accept: accepted connection");
       ep = grpc_tcp_create(grpc_winsocket_create(sock));
     }
   } else {
-    gpr_log(GPR_DEBUG, "on_accept: shutting down");
     closesocket(sock);
     gpr_mu_lock(&sp->server->mu);
     if (0 == --sp->server->active_ports) {

src/core/iomgr/tcp_windows.c

@@ -93,14 +93,11 @@ typedef struct grpc_tcp {
 } grpc_tcp;
 
 static void tcp_ref(grpc_tcp *tcp) {
-  gpr_log(GPR_DEBUG, "tcp_ref");
   gpr_ref(&tcp->refcount);
 }
 
 static void tcp_unref(grpc_tcp *tcp) {
-  gpr_log(GPR_DEBUG, "tcp_unref");
   if (gpr_unref(&tcp->refcount)) {
-    gpr_log(GPR_DEBUG, "tcp_unref: destroying");
     gpr_slice_buffer_destroy(&tcp->write_slices);
     grpc_winsocket_orphan(tcp->socket);
     gpr_free(tcp);
@@ -126,24 +123,19 @@ static void on_read(void *tcpp, int success) {
     return;
   }
 
-  gpr_log(GPR_DEBUG, "on_read");
   tcp->outstanding_read = 0;
 
   if (socket->read_info.wsa_error != 0) {
     char *utf8_message = gpr_format_message(info->wsa_error);
-    __debugbreak();
-    gpr_log(GPR_ERROR, "ReadFile overlapped error: %s", utf8_message);
     gpr_free(utf8_message);
     status = GRPC_ENDPOINT_CB_ERROR;
   } else {
     if (info->bytes_transfered != 0) {
       sub = gpr_slice_sub(tcp->read_slice, 0, info->bytes_transfered);
-      gpr_log(GPR_DEBUG, "on_read: calling callback");
       status = GRPC_ENDPOINT_CB_OK;
       slice = ⊂
       nslices = 1;
     } else {
-      gpr_log(GPR_DEBUG, "on_read: closed socket");
       gpr_slice_unref(tcp->read_slice);
       status = GRPC_ENDPOINT_CB_EOF;
     }
@@ -174,27 +166,22 @@ static void win_notify_on_read(grpc_endpoint *ep,
   buffer.len = GPR_SLICE_LENGTH(tcp->read_slice);
   buffer.buf = (char *)GPR_SLICE_START_PTR(tcp->read_slice);
 
-  gpr_log(GPR_DEBUG, "win_notify_on_read: calling WSARecv without overlap");
   status = WSARecv(tcp->socket->socket, &buffer, 1, &bytes_read, &flags,
                    NULL, NULL);
   info->wsa_error = status == 0 ? 0 : WSAGetLastError();
 
   if (info->wsa_error != WSAEWOULDBLOCK) {
-    gpr_log(GPR_DEBUG, "got response immediately, calling on_read");
     info->bytes_transfered = bytes_read;
     /* This might heavily recurse. */
     on_read(tcp, 1);
     return;
   }
 
-  gpr_log(GPR_DEBUG, "got WSAEWOULDBLOCK - calling WSARecv with overlap");
-
   memset(&tcp->socket->read_info.overlapped, 0, sizeof(OVERLAPPED));
   status = WSARecv(tcp->socket->socket, &buffer, 1, &bytes_read, &flags,
                    &info->overlapped, NULL);
 
   if (status == 0) {
-    gpr_log(GPR_DEBUG, "got response immediately, but we're going to sleep");
     grpc_socket_notify_on_read(tcp->socket, on_read, tcp);
     return;
   }
@@ -213,7 +200,6 @@ static void win_notify_on_read(grpc_endpoint *ep,
     return;
   }
 
-  gpr_log(GPR_DEBUG, "waiting on the IO completion port now");
   grpc_socket_notify_on_read(tcp->socket, on_read, tcp);
 }
 
@@ -227,8 +213,6 @@ static void on_write(void *tcpp, int success) {
 
   GPR_ASSERT(tcp->outstanding_write);
 
-  gpr_log(GPR_DEBUG, "on_write");
-
   if (!success) {
     tcp_unref(tcp);
     cb(opaque, GRPC_ENDPOINT_CB_SHUTDOWN);
@@ -268,8 +252,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
   GPR_ASSERT(!tcp->outstanding_write);
   tcp_ref(tcp);
 
-  gpr_log(GPR_DEBUG, "win_write");
-
   tcp->outstanding_write = 1;
   tcp->write_cb = cb;
   tcp->write_user_data = arg;
@@ -285,14 +267,12 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
     buffers[i].buf = (char *)GPR_SLICE_START_PTR(tcp->write_slices.slices[i]);
   }
 
-  gpr_log(GPR_DEBUG, "win_write: calling WSASend without overlap");
   status = WSASend(socket->socket, buffers, tcp->write_slices.count,
                    &bytes_sent, 0, NULL, NULL);
   info->wsa_error = status == 0 ? 0 : WSAGetLastError();
 
   if (info->wsa_error != WSAEWOULDBLOCK) {
     grpc_endpoint_write_status ret = GRPC_ENDPOINT_WRITE_ERROR;
-    gpr_log(GPR_DEBUG, "got response immediately, cleaning up and leaving");
     if (status == 0) {
       ret = GRPC_ENDPOINT_WRITE_DONE;
       GPR_ASSERT(bytes_sent == tcp->write_slices.length);
@@ -308,8 +288,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
     return ret;
   }
 
-  gpr_log(GPR_DEBUG, "got WSAEWOULDBLOCK - calling WSASend with overlap");
-
   memset(&socket->write_info, 0, sizeof(OVERLAPPED));
   status = WSASend(socket->socket, buffers, tcp->write_slices.count,
                    &bytes_sent, 0, &socket->write_info.overlapped, NULL);
@@ -327,9 +305,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
       tcp_unref(tcp);
       return GRPC_ENDPOINT_WRITE_ERROR;
     }
-    gpr_log(GPR_DEBUG, "win_write: got pending op");
-  } else {
-    gpr_log(GPR_DEBUG, "wrote data immediately - but we're going to sleep");
   }
 
   grpc_socket_notify_on_write(socket, on_write, tcp);
@@ -338,19 +313,16 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
 
 static void win_add_to_pollset(grpc_endpoint *ep, grpc_pollset *pollset) {
   grpc_tcp *tcp = (grpc_tcp *) ep;
-  gpr_log(GPR_DEBUG, "win_add_to_pollset");
   grpc_iocp_add_socket(tcp->socket);
 }
 
 static void win_shutdown(grpc_endpoint *ep) {
   grpc_tcp *tcp = (grpc_tcp *) ep;
-  gpr_log(GPR_DEBUG, "win_shutdown");
   grpc_winsocket_shutdown(tcp->socket);
 }
 
 static void win_destroy(grpc_endpoint *ep) {
   grpc_tcp *tcp = (grpc_tcp *) ep;
-  gpr_log(GPR_DEBUG, "win_destroy");
   tcp_unref(tcp);
 }