Skip to content
Snippets Groups Projects
Commit 5618a9d6 authored by Jan Tattermusch's avatar Jan Tattermusch
Browse files

removed chatty log messages on windows

parent 3ac966b6
No related branches found
No related tags found
No related merge requests found
...@@ -78,7 +78,6 @@ static void do_iocp_work() { ...@@ -78,7 +78,6 @@ static void do_iocp_work() {
if (overlapped == &g_iocp_custom_overlap) { if (overlapped == &g_iocp_custom_overlap) {
if (completion_key == (ULONG_PTR) &g_iocp_kick_token) { if (completion_key == (ULONG_PTR) &g_iocp_kick_token) {
/* We were awoken from a kick. */ /* We were awoken from a kick. */
gpr_log(GPR_DEBUG, "do_iocp_work - got a kick");
return; return;
} }
gpr_log(GPR_ERROR, "Unknown custom completion key."); gpr_log(GPR_ERROR, "Unknown custom completion key.");
...@@ -87,10 +86,8 @@ static void do_iocp_work() { ...@@ -87,10 +86,8 @@ static void do_iocp_work() {
socket = (grpc_winsocket*) completion_key; socket = (grpc_winsocket*) completion_key;
if (overlapped == &socket->write_info.overlapped) { if (overlapped == &socket->write_info.overlapped) {
gpr_log(GPR_DEBUG, "do_iocp_work - got write packet");
info = &socket->write_info; info = &socket->write_info;
} else if (overlapped == &socket->read_info.overlapped) { } else if (overlapped == &socket->read_info.overlapped) {
gpr_log(GPR_DEBUG, "do_iocp_work - got read packet");
info = &socket->read_info; info = &socket->read_info;
} else { } else {
gpr_log(GPR_ERROR, "Unknown IOCP operation"); gpr_log(GPR_ERROR, "Unknown IOCP operation");
...@@ -98,8 +95,6 @@ static void do_iocp_work() { ...@@ -98,8 +95,6 @@ static void do_iocp_work() {
} }
success = WSAGetOverlappedResult(socket->socket, &info->overlapped, &bytes, success = WSAGetOverlappedResult(socket->socket, &info->overlapped, &bytes,
FALSE, &flags); FALSE, &flags);
gpr_log(GPR_DEBUG, "bytes: %u, flags: %u - op %s %s", bytes, flags,
success ? "succeeded" : "failed", socket->orphan ? "orphan" : "");
if (socket->orphan) { if (socket->orphan) {
grpc_winsocket_destroy(socket); grpc_winsocket_destroy(socket);
gpr_atm_full_fetch_add(&g_orphans, -1); gpr_atm_full_fetch_add(&g_orphans, -1);
...@@ -189,11 +184,9 @@ static void socket_notify_on_iocp(grpc_winsocket *socket, ...@@ -189,11 +184,9 @@ static void socket_notify_on_iocp(grpc_winsocket *socket,
if (info->has_pending_iocp) { if (info->has_pending_iocp) {
run_now = 1; run_now = 1;
info->has_pending_iocp = 0; info->has_pending_iocp = 0;
gpr_log(GPR_DEBUG, "socket_notify_on_iocp - runs now");
} else { } else {
info->cb = cb; info->cb = cb;
info->opaque = opaque; info->opaque = opaque;
gpr_log(GPR_DEBUG, "socket_notify_on_iocp - queued");
} }
gpr_mu_unlock(&socket->state_mu); gpr_mu_unlock(&socket->state_mu);
if (run_now) cb(opaque, 1); if (run_now) cb(opaque, 1);
...@@ -201,13 +194,11 @@ static void socket_notify_on_iocp(grpc_winsocket *socket, ...@@ -201,13 +194,11 @@ static void socket_notify_on_iocp(grpc_winsocket *socket,
void grpc_socket_notify_on_write(grpc_winsocket *socket, void grpc_socket_notify_on_write(grpc_winsocket *socket,
void(*cb)(void *, int), void *opaque) { 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); socket_notify_on_iocp(socket, cb, opaque, &socket->write_info);
} }
void grpc_socket_notify_on_read(grpc_winsocket *socket, void grpc_socket_notify_on_read(grpc_winsocket *socket,
void(*cb)(void *, int), void *opaque) { 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); socket_notify_on_iocp(socket, cb, opaque, &socket->read_info);
} }
......
...@@ -107,18 +107,14 @@ grpc_resolved_addresses *grpc_blocking_resolve_address( ...@@ -107,18 +107,14 @@ grpc_resolved_addresses *grpc_blocking_resolve_address(
i++; i++;
} }
/* Temporary logging, to help identify flakiness in dualstack_socket_test. */
{ {
const gpr_timespec delay = gpr_time_sub(gpr_now(), start_time); const gpr_timespec delay = gpr_time_sub(gpr_now(), start_time);
const int delay_ms = const int delay_ms =
delay.tv_sec * GPR_MS_PER_SEC + delay.tv_nsec / GPR_NS_PER_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++) { for (i = 0; i < addrs->naddrs; i++) {
char *buf; char *buf;
grpc_sockaddr_to_string(&buf, (struct sockaddr *)&addrs->addrs[i].addr, grpc_sockaddr_to_string(&buf, (struct sockaddr *)&addrs->addrs[i].addr,
0); 0);
gpr_log(GPR_INFO, "logspam: [%d] %s", i, buf);
gpr_free(buf); gpr_free(buf);
} }
} }
......
...@@ -46,7 +46,6 @@ ...@@ -46,7 +46,6 @@
grpc_winsocket *grpc_winsocket_create(SOCKET socket) { grpc_winsocket *grpc_winsocket_create(SOCKET socket) {
grpc_winsocket *r = gpr_malloc(sizeof(grpc_winsocket)); grpc_winsocket *r = gpr_malloc(sizeof(grpc_winsocket));
gpr_log(GPR_DEBUG, "grpc_winsocket_create");
memset(r, 0, sizeof(grpc_winsocket)); memset(r, 0, sizeof(grpc_winsocket));
r->socket = socket; r->socket = socket;
gpr_mu_init(&r->state_mu); gpr_mu_init(&r->state_mu);
...@@ -61,13 +60,11 @@ static void shutdown_op(grpc_winsocket_callback_info *info) { ...@@ -61,13 +60,11 @@ static void shutdown_op(grpc_winsocket_callback_info *info) {
} }
void grpc_winsocket_shutdown(grpc_winsocket *socket) { void grpc_winsocket_shutdown(grpc_winsocket *socket) {
gpr_log(GPR_DEBUG, "grpc_winsocket_shutdown");
shutdown_op(&socket->read_info); shutdown_op(&socket->read_info);
shutdown_op(&socket->write_info); shutdown_op(&socket->write_info);
} }
void grpc_winsocket_orphan(grpc_winsocket *socket) { void grpc_winsocket_orphan(grpc_winsocket *socket) {
gpr_log(GPR_DEBUG, "grpc_winsocket_orphan");
grpc_iocp_socket_orphan(socket); grpc_iocp_socket_orphan(socket);
socket->orphan = 1; socket->orphan = 1;
grpc_iomgr_unref(); grpc_iomgr_unref();
......
...@@ -102,7 +102,6 @@ static void on_connect(void *acp, int success) { ...@@ -102,7 +102,6 @@ static void on_connect(void *acp, int success) {
gpr_free(utf8_message); gpr_free(utf8_message);
goto finish; goto finish;
} else { } else {
gpr_log(GPR_DEBUG, "on_connect: connection established");
ep = grpc_tcp_create(ac->socket); ep = grpc_tcp_create(ac->socket);
goto finish; goto finish;
} }
...@@ -179,9 +178,7 @@ void grpc_tcp_client_connect(void(*cb)(void *arg, grpc_endpoint *tcp), ...@@ -179,9 +178,7 @@ void grpc_tcp_client_connect(void(*cb)(void *arg, grpc_endpoint *tcp),
info = &socket->write_info; info = &socket->write_info;
success = ConnectEx(sock, addr, addr_len, NULL, 0, NULL, &info->overlapped); success = ConnectEx(sock, addr, addr_len, NULL, 0, NULL, &info->overlapped);
if (success) { if (!success) {
gpr_log(GPR_DEBUG, "connected immediately - but we still go to sleep");
} else {
int error = WSAGetLastError(); int error = WSAGetLastError();
if (error != ERROR_IO_PENDING) { if (error != ERROR_IO_PENDING) {
message = "ConnectEx failed: %s"; message = "ConnectEx failed: %s";
...@@ -189,7 +186,6 @@ void grpc_tcp_client_connect(void(*cb)(void *arg, grpc_endpoint *tcp), ...@@ -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 = gpr_malloc(sizeof(async_connect));
ac->cb = cb; ac->cb = cb;
ac->cb_arg = arg; ac->cb_arg = arg;
......
...@@ -195,9 +195,7 @@ static void start_accept(server_port *port) { ...@@ -195,9 +195,7 @@ static void start_accept(server_port *port) {
addrlen, addrlen, &bytes_received, addrlen, addrlen, &bytes_received,
&port->socket->read_info.overlapped); &port->socket->read_info.overlapped);
if (success) { if (!success) {
gpr_log(GPR_DEBUG, "accepted immediately - but we still go to sleep");
} else {
int error = WSAGetLastError(); int error = WSAGetLastError();
if (error != ERROR_IO_PENDING) { if (error != ERROR_IO_PENDING) {
message = "AcceptEx failed: %s"; message = "AcceptEx failed: %s";
...@@ -234,11 +232,9 @@ static void on_accept(void *arg, int success) { ...@@ -234,11 +232,9 @@ static void on_accept(void *arg, int success) {
gpr_free(utf8_message); gpr_free(utf8_message);
closesocket(sock); closesocket(sock);
} else { } else {
gpr_log(GPR_DEBUG, "on_accept: accepted connection");
ep = grpc_tcp_create(grpc_winsocket_create(sock)); ep = grpc_tcp_create(grpc_winsocket_create(sock));
} }
} else { } else {
gpr_log(GPR_DEBUG, "on_accept: shutting down");
closesocket(sock); closesocket(sock);
gpr_mu_lock(&sp->server->mu); gpr_mu_lock(&sp->server->mu);
if (0 == --sp->server->active_ports) { if (0 == --sp->server->active_ports) {
......
...@@ -93,14 +93,11 @@ typedef struct grpc_tcp { ...@@ -93,14 +93,11 @@ typedef struct grpc_tcp {
} grpc_tcp; } grpc_tcp;
static void tcp_ref(grpc_tcp *tcp) { static void tcp_ref(grpc_tcp *tcp) {
gpr_log(GPR_DEBUG, "tcp_ref");
gpr_ref(&tcp->refcount); gpr_ref(&tcp->refcount);
} }
static void tcp_unref(grpc_tcp *tcp) { static void tcp_unref(grpc_tcp *tcp) {
gpr_log(GPR_DEBUG, "tcp_unref");
if (gpr_unref(&tcp->refcount)) { if (gpr_unref(&tcp->refcount)) {
gpr_log(GPR_DEBUG, "tcp_unref: destroying");
gpr_slice_buffer_destroy(&tcp->write_slices); gpr_slice_buffer_destroy(&tcp->write_slices);
grpc_winsocket_orphan(tcp->socket); grpc_winsocket_orphan(tcp->socket);
gpr_free(tcp); gpr_free(tcp);
...@@ -126,24 +123,19 @@ static void on_read(void *tcpp, int success) { ...@@ -126,24 +123,19 @@ static void on_read(void *tcpp, int success) {
return; return;
} }
gpr_log(GPR_DEBUG, "on_read");
tcp->outstanding_read = 0; tcp->outstanding_read = 0;
if (socket->read_info.wsa_error != 0) { if (socket->read_info.wsa_error != 0) {
char *utf8_message = gpr_format_message(info->wsa_error); char *utf8_message = gpr_format_message(info->wsa_error);
__debugbreak();
gpr_log(GPR_ERROR, "ReadFile overlapped error: %s", utf8_message);
gpr_free(utf8_message); gpr_free(utf8_message);
status = GRPC_ENDPOINT_CB_ERROR; status = GRPC_ENDPOINT_CB_ERROR;
} else { } else {
if (info->bytes_transfered != 0) { if (info->bytes_transfered != 0) {
sub = gpr_slice_sub(tcp->read_slice, 0, info->bytes_transfered); sub = gpr_slice_sub(tcp->read_slice, 0, info->bytes_transfered);
gpr_log(GPR_DEBUG, "on_read: calling callback");
status = GRPC_ENDPOINT_CB_OK; status = GRPC_ENDPOINT_CB_OK;
slice = &sub; slice = &sub;
nslices = 1; nslices = 1;
} else { } else {
gpr_log(GPR_DEBUG, "on_read: closed socket");
gpr_slice_unref(tcp->read_slice); gpr_slice_unref(tcp->read_slice);
status = GRPC_ENDPOINT_CB_EOF; status = GRPC_ENDPOINT_CB_EOF;
} }
...@@ -174,27 +166,22 @@ static void win_notify_on_read(grpc_endpoint *ep, ...@@ -174,27 +166,22 @@ static void win_notify_on_read(grpc_endpoint *ep,
buffer.len = GPR_SLICE_LENGTH(tcp->read_slice); buffer.len = GPR_SLICE_LENGTH(tcp->read_slice);
buffer.buf = (char *)GPR_SLICE_START_PTR(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, status = WSARecv(tcp->socket->socket, &buffer, 1, &bytes_read, &flags,
NULL, NULL); NULL, NULL);
info->wsa_error = status == 0 ? 0 : WSAGetLastError(); info->wsa_error = status == 0 ? 0 : WSAGetLastError();
if (info->wsa_error != WSAEWOULDBLOCK) { if (info->wsa_error != WSAEWOULDBLOCK) {
gpr_log(GPR_DEBUG, "got response immediately, calling on_read");
info->bytes_transfered = bytes_read; info->bytes_transfered = bytes_read;
/* This might heavily recurse. */ /* This might heavily recurse. */
on_read(tcp, 1); on_read(tcp, 1);
return; return;
} }
gpr_log(GPR_DEBUG, "got WSAEWOULDBLOCK - calling WSARecv with overlap");
memset(&tcp->socket->read_info.overlapped, 0, sizeof(OVERLAPPED)); memset(&tcp->socket->read_info.overlapped, 0, sizeof(OVERLAPPED));
status = WSARecv(tcp->socket->socket, &buffer, 1, &bytes_read, &flags, status = WSARecv(tcp->socket->socket, &buffer, 1, &bytes_read, &flags,
&info->overlapped, NULL); &info->overlapped, NULL);
if (status == 0) { 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); grpc_socket_notify_on_read(tcp->socket, on_read, tcp);
return; return;
} }
...@@ -213,7 +200,6 @@ static void win_notify_on_read(grpc_endpoint *ep, ...@@ -213,7 +200,6 @@ static void win_notify_on_read(grpc_endpoint *ep,
return; return;
} }
gpr_log(GPR_DEBUG, "waiting on the IO completion port now");
grpc_socket_notify_on_read(tcp->socket, on_read, tcp); grpc_socket_notify_on_read(tcp->socket, on_read, tcp);
} }
...@@ -227,8 +213,6 @@ static void on_write(void *tcpp, int success) { ...@@ -227,8 +213,6 @@ static void on_write(void *tcpp, int success) {
GPR_ASSERT(tcp->outstanding_write); GPR_ASSERT(tcp->outstanding_write);
gpr_log(GPR_DEBUG, "on_write");
if (!success) { if (!success) {
tcp_unref(tcp); tcp_unref(tcp);
cb(opaque, GRPC_ENDPOINT_CB_SHUTDOWN); cb(opaque, GRPC_ENDPOINT_CB_SHUTDOWN);
...@@ -268,8 +252,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep, ...@@ -268,8 +252,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
GPR_ASSERT(!tcp->outstanding_write); GPR_ASSERT(!tcp->outstanding_write);
tcp_ref(tcp); tcp_ref(tcp);
gpr_log(GPR_DEBUG, "win_write");
tcp->outstanding_write = 1; tcp->outstanding_write = 1;
tcp->write_cb = cb; tcp->write_cb = cb;
tcp->write_user_data = arg; tcp->write_user_data = arg;
...@@ -285,14 +267,12 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep, ...@@ -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]); 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, status = WSASend(socket->socket, buffers, tcp->write_slices.count,
&bytes_sent, 0, NULL, NULL); &bytes_sent, 0, NULL, NULL);
info->wsa_error = status == 0 ? 0 : WSAGetLastError(); info->wsa_error = status == 0 ? 0 : WSAGetLastError();
if (info->wsa_error != WSAEWOULDBLOCK) { if (info->wsa_error != WSAEWOULDBLOCK) {
grpc_endpoint_write_status ret = GRPC_ENDPOINT_WRITE_ERROR; grpc_endpoint_write_status ret = GRPC_ENDPOINT_WRITE_ERROR;
gpr_log(GPR_DEBUG, "got response immediately, cleaning up and leaving");
if (status == 0) { if (status == 0) {
ret = GRPC_ENDPOINT_WRITE_DONE; ret = GRPC_ENDPOINT_WRITE_DONE;
GPR_ASSERT(bytes_sent == tcp->write_slices.length); GPR_ASSERT(bytes_sent == tcp->write_slices.length);
...@@ -308,8 +288,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep, ...@@ -308,8 +288,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
return ret; return ret;
} }
gpr_log(GPR_DEBUG, "got WSAEWOULDBLOCK - calling WSASend with overlap");
memset(&socket->write_info, 0, sizeof(OVERLAPPED)); memset(&socket->write_info, 0, sizeof(OVERLAPPED));
status = WSASend(socket->socket, buffers, tcp->write_slices.count, status = WSASend(socket->socket, buffers, tcp->write_slices.count,
&bytes_sent, 0, &socket->write_info.overlapped, NULL); &bytes_sent, 0, &socket->write_info.overlapped, NULL);
...@@ -327,9 +305,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep, ...@@ -327,9 +305,6 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep,
tcp_unref(tcp); tcp_unref(tcp);
return GRPC_ENDPOINT_WRITE_ERROR; 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); grpc_socket_notify_on_write(socket, on_write, tcp);
...@@ -338,19 +313,16 @@ static grpc_endpoint_write_status win_write(grpc_endpoint *ep, ...@@ -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) { static void win_add_to_pollset(grpc_endpoint *ep, grpc_pollset *pollset) {
grpc_tcp *tcp = (grpc_tcp *) ep; grpc_tcp *tcp = (grpc_tcp *) ep;
gpr_log(GPR_DEBUG, "win_add_to_pollset");
grpc_iocp_add_socket(tcp->socket); grpc_iocp_add_socket(tcp->socket);
} }
static void win_shutdown(grpc_endpoint *ep) { static void win_shutdown(grpc_endpoint *ep) {
grpc_tcp *tcp = (grpc_tcp *) ep; grpc_tcp *tcp = (grpc_tcp *) ep;
gpr_log(GPR_DEBUG, "win_shutdown");
grpc_winsocket_shutdown(tcp->socket); grpc_winsocket_shutdown(tcp->socket);
} }
static void win_destroy(grpc_endpoint *ep) { static void win_destroy(grpc_endpoint *ep) {
grpc_tcp *tcp = (grpc_tcp *) ep; grpc_tcp *tcp = (grpc_tcp *) ep;
gpr_log(GPR_DEBUG, "win_destroy");
tcp_unref(tcp); tcp_unref(tcp);
} }
......
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment