Merge branch 'master' of github.com:google/grpc into private_build

7 files changed, 18 insertions, 56 deletions

diff --git a/src/core/iomgr/iocp_windows.c b/src/core/iomgr/iocp_windows.c
index aec626509a..7968729353 100644
--- a/src/core/iomgr/iocp_windows.c
+++ b/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);
 }
 
diff --git a/src/core/iomgr/resolve_address_windows.c b/src/core/iomgr/resolve_address_windows.c
index 877b3f35ed..ac31dadd9d 100644
--- a/src/core/iomgr/resolve_address_windows.c
+++ b/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);
     }
   }
diff --git a/src/core/iomgr/socket_windows.c b/src/core/iomgr/socket_windows.c
index 22dad41783..91268c04e6 100644
--- a/src/core/iomgr/socket_windows.c
+++ b/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();
diff --git a/src/core/iomgr/tcp_client_windows.c b/src/core/iomgr/tcp_client_windows.c
index 181d89cb6d..00c8da601b 100644
--- a/src/core/iomgr/tcp_client_windows.c
+++ b/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;
diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c
index 597a2a62d3..86721e9c95 100644
--- a/src/core/iomgr/tcp_posix.c
+++ b/src/core/iomgr/tcp_posix.c
@@ -46,6 +46,7 @@
 
 #include "src/core/support/string.h"
 #include "src/core/debug/trace.h"
+#include "src/core/profiling/timers.h"
 #include <grpc/support/alloc.h>
 #include <grpc/support/log.h>
 #include <grpc/support/slice.h>
@@ -326,6 +327,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) {
   gpr_slice *final_slices;
   size_t final_nslices;
 
+  GRPC_TIMER_MARK(HANDLE_READ_BEGIN, 0);
   slice_state_init(&read_state, static_read_slices, INLINE_SLICE_BUFFER_SIZE,
                    0);
 
@@ -348,9 +350,11 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) {
     msg.msg_controllen = 0;
     msg.msg_flags = 0;
 
+    GRPC_TIMER_MARK(RECVMSG_BEGIN, 0);
     do {
       read_bytes = recvmsg(tcp->fd, &msg, 0);
     } while (read_bytes < 0 && errno == EINTR);
+    GRPC_TIMER_MARK(RECVMSG_END, 0);
 
     if (read_bytes < allocated_bytes) {
       /* TODO(klempner): Consider a second read first, in hopes of getting a
@@ -402,6 +406,7 @@ static void grpc_tcp_handle_read(void *arg /* grpc_tcp */, int success) {
       ++iov_size;
     }
   }
+  GRPC_TIMER_MARK(HANDLE_READ_END, 0);
 }
 
 static void grpc_tcp_notify_on_read(grpc_endpoint *ep, grpc_endpoint_read_cb cb,
@@ -433,10 +438,12 @@ static grpc_endpoint_write_status grpc_tcp_flush(grpc_tcp *tcp) {
     msg.msg_controllen = 0;
     msg.msg_flags = 0;
 
+    GRPC_TIMER_MARK(SENDMSG_BEGIN, 0);
     do {
       /* TODO(klempner): Cork if this is a partial write */
       sent_length = sendmsg(tcp->fd, &msg, 0);
     } while (sent_length < 0 && errno == EINTR);
+    GRPC_TIMER_MARK(SENDMSG_END, 0);
 
     if (sent_length < 0) {
       if (errno == EAGAIN) {
@@ -472,6 +479,7 @@ static void grpc_tcp_handle_write(void *arg /* grpc_tcp */, int success) {
     return;
   }
 
+  GRPC_TIMER_MARK(CB_WRITE_BEGIN, 0);
   write_status = grpc_tcp_flush(tcp);
   if (write_status == GRPC_ENDPOINT_WRITE_PENDING) {
     grpc_fd_notify_on_write(tcp->em_fd, &tcp->write_closure);
@@ -487,6 +495,7 @@ static void grpc_tcp_handle_write(void *arg /* grpc_tcp */, int success) {
     cb(tcp->write_user_data, cb_status);
     grpc_tcp_unref(tcp);
   }
+  GRPC_TIMER_MARK(CB_WRITE_END, 0);
 }
 
 static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep,
@@ -509,6 +518,7 @@ static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep,
     }
   }
 
+  GRPC_TIMER_MARK(WRITE_BEGIN, 0);
   GPR_ASSERT(tcp->write_cb == NULL);
   slice_state_init(&tcp->write_state, slices, nslices, nslices);
 
@@ -522,6 +532,7 @@ static grpc_endpoint_write_status grpc_tcp_write(grpc_endpoint *ep,
     grpc_fd_notify_on_write(tcp->em_fd, &tcp->write_closure);
   }
 
+  GRPC_TIMER_MARK(WRITE_END, 0);
   return status;
 }
 
diff --git a/src/core/iomgr/tcp_server_windows.c b/src/core/iomgr/tcp_server_windows.c
index a43d5670a4..6e10da97cc 100644
--- a/src/core/iomgr/tcp_server_windows.c
+++ b/src/core/iomgr/tcp_server_windows.c
@@ -191,13 +191,13 @@ static void start_accept(server_port *port) {
     goto failure;
   }
 
+  /* TODO(jtattermusch): probably a race here, we regularly get use-after-free on server shutdown */
+  GPR_ASSERT(port->socket != 0xfeeefeee);
   success = port->AcceptEx(port->socket->socket, sock, port->addresses, 0,
                            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 +234,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) {
@@ -248,7 +246,9 @@ static void on_accept(void *arg, int success) {
   }
 
   if (ep) sp->server->cb(sp->server->cb_arg, ep);
-  start_accept(sp);
+  if (success) {
+    start_accept(sp);
+  }
 }
 
 static int add_socket_to_server(grpc_tcp_server *s, SOCKET sock,
diff --git a/src/core/iomgr/tcp_windows.c b/src/core/iomgr/tcp_windows.c
index ec5496e7ee..71534eaa3d 100644
--- a/src/core/iomgr/tcp_windows.c
+++ b/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,20 @@ 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 = &sub;
       nslices = 1;
     } else {
-      gpr_log(GPR_DEBUG, "on_read: closed socket");
       gpr_slice_unref(tcp->read_slice);
       status = GRPC_ENDPOINT_CB_EOF;
     }
@@ -174,27 +167,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 +201,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 +214,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);
@@ -265,13 +250,9 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
   WSABUF *allocated = NULL;
   WSABUF *buffers = local_buffers;
 
-  GPR_ASSERT(nslices != 0);
-  GPR_ASSERT(GPR_SLICE_LENGTH(slices[0]) != 0);
   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;
@@ -287,14 +268,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);
@@ -310,8 +289,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);
@@ -329,9 +306,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);
@@ -340,19 +314,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);
 }