From 66a38bc8b9c4f3f4bc5c12caab5b2cd308839236 Mon Sep 17 00:00:00 2001 From: Michael Graeb Date: Tue, 24 May 2022 16:41:08 -0700 Subject: [PATCH] Fix error codes reported by windows sockets. (#489) Issue: Discovered when running tests in Debug on Windows. The error codes reported from socket functions were NOT what was expected. Investigation revealed that the value from `WSAGetLastError()` would get reset to 0 as a side-effect of logging. This was only happening in Debug, which is why we weren't catching it in CI. Therefore: Always call `WSAGetLastError()` **immediately** after a socket function fails, and store the value for use later. --- source/windows/iocp/socket.c | 159 +++++++++++++++++++++-------------- 1 file changed, 97 insertions(+), 62 deletions(-) diff --git a/source/windows/iocp/socket.c b/source/windows/iocp/socket.c index d504f5fd7..d06edb716 100644 --- a/source/windows/iocp/socket.c +++ b/source/windows/iocp/socket.c @@ -306,6 +306,12 @@ struct iocp_socket { static int s_create_socket(struct aws_socket *sock, const struct aws_socket_options *options) { SOCKET handle = socket(s_convert_domain(options->domain), s_convert_type(options->type), 0); + if (handle == INVALID_SOCKET) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ + AWS_LOGF_ERROR(AWS_LS_IO_SOCKET, "id=static: socket() call failed with WSAError %d", wsa_err); + return aws_raise_error(s_determine_socket_error(wsa_err)); + } + AWS_LOGF_DEBUG( AWS_LS_IO_SOCKET, "id=%p handle=%p: initializing with domain %d and type %d", @@ -314,20 +320,24 @@ static int s_create_socket(struct aws_socket *sock, const struct aws_socket_opti options->domain, options->type); u_long non_blocking = 1; - if (handle != INVALID_SOCKET && !ioctlsocket(handle, FIONBIO, &non_blocking)) { - sock->io_handle.data.handle = (HANDLE)handle; - sock->io_handle.additional_data = NULL; - if (aws_socket_set_options(sock, options)) { - closesocket(handle); - sock->io_handle.data.handle = (HANDLE)INVALID_SOCKET; - return AWS_OP_ERR; - } - return AWS_OP_SUCCESS; + if (ioctlsocket(handle, FIONBIO, &non_blocking) != 0) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ + AWS_LOGF_ERROR(AWS_LS_IO_SOCKET, "id=static: ioctlsocket() call failed with WSAError %d", wsa_err); + aws_raise_error(s_determine_socket_error(wsa_err)); + goto error; } - int error_code = WSAGetLastError(); - int aws_error = s_determine_socket_error(error_code); - return aws_raise_error(aws_error); + sock->io_handle.data.handle = (HANDLE)handle; + sock->io_handle.additional_data = NULL; + if (aws_socket_set_options(sock, options)) { + goto error; + } + return AWS_OP_SUCCESS; + +error: + closesocket(handle); + sock->io_handle.data.handle = (HANDLE)INVALID_SOCKET; + return AWS_OP_ERR; } static int s_socket_init( @@ -596,14 +606,15 @@ static int s_ipv4_stream_connection_success(struct aws_socket *socket) { struct iocp_socket *socket_impl = socket->impl; if (getsockopt( (SOCKET)socket->io_handle.data.handle, SOL_SOCKET, SO_ERROR, (char *)&connect_result, &result_length) < 0) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: failed to determine connection error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); socket_impl->vtable->connection_error(socket, error); return AWS_OP_ERR; @@ -634,13 +645,14 @@ static int s_ipv4_stream_connection_success(struct aws_socket *socket) { struct sockaddr_in *s = (struct sockaddr_in *)&address; port = ntohs(s->sin_port); if (!InetNtopA(AF_INET, &s->sin_addr, socket->local_endpoint.address, sizeof(socket->local_endpoint.address))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: determining local endpoint failed", (void *)socket, (void *)socket->io_handle.data.handle); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); socket_impl->vtable->connection_error(socket, error); return AWS_OP_ERR; @@ -654,14 +666,15 @@ static int s_ipv4_stream_connection_success(struct aws_socket *socket) { (int)port); socket->local_endpoint.port = port; } else { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: getsockname() failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); socket_impl->vtable->connection_error(socket, error); return AWS_OP_ERR; @@ -688,14 +701,15 @@ static int s_ipv6_stream_connection_success(struct aws_socket *socket) { struct iocp_socket *socket_impl = socket->impl; if (getsockopt( (SOCKET)socket->io_handle.data.handle, SOL_SOCKET, SO_ERROR, (char *)&connect_result, &result_length) < 0) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: failed to determine connection error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); socket_impl->vtable->connection_error(socket, error); return AWS_OP_ERR; @@ -727,13 +741,14 @@ static int s_ipv6_stream_connection_success(struct aws_socket *socket) { port = ntohs(s->sin6_port); if (!InetNtopA( AF_INET6, &s->sin6_addr, socket->local_endpoint.address, sizeof(socket->local_endpoint.address))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: determining local endpoint failed", (void *)socket, (void *)socket->io_handle.data.handle); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); socket_impl->vtable->connection_error(socket, error); return AWS_OP_ERR; @@ -746,14 +761,15 @@ static int s_ipv6_stream_connection_success(struct aws_socket *socket) { socket->local_endpoint.address, (int)port); } else { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: getsockname() failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); socket_impl->vtable->connection_error(socket, error); return AWS_OP_ERR; @@ -907,13 +923,14 @@ static inline int s_tcp_connect( int reuse = 1; if (setsockopt((SOCKET)socket->io_handle.data.handle, SOL_SOCKET, SO_REUSEADDR, (char *)&reuse, sizeof(int))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_WARN( AWS_LS_IO_SOCKET, "id=%p handle=%p: setsockopt() call for enabling SO_REUSEADDR failed with WSAError %d", (void *)socket, (void *)socket->io_handle.data.handle, - WSAGetLastError()); - return aws_raise_error(s_determine_socket_error(WSAGetLastError())); + wsa_err); + return aws_raise_error(s_determine_socket_error(wsa_err)); } struct socket_connect_args *connect_args = aws_mem_calloc(socket->allocator, 1, sizeof(struct socket_connect_args)); @@ -994,6 +1011,8 @@ static inline int s_tcp_connect( return AWS_OP_SUCCESS; } +/* This should be called IMMEDIATELY after failure. + * Otherwise, WSAGetLastError() could get cleared accidentally by a logging call */ static inline int s_convert_pton_error(int pton_err) { if (pton_err == 0) { return AWS_IO_SOCKET_INVALID_ADDRESS; @@ -1021,6 +1040,7 @@ static int s_ipv4_stream_connect( int err = inet_pton(AF_INET, remote_endpoint->address, &(addr_in.sin_addr)); if (err != 1) { + int aws_err = s_convert_pton_error(err); /* call before logging or WSAError may get cleared */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: failed to parse address %s:%d.", @@ -1028,7 +1048,7 @@ static int s_ipv4_stream_connect( (void *)socket->io_handle.data.handle, remote_endpoint->address, (int)remote_endpoint->port); - return aws_raise_error(s_convert_pton_error(err)); + return aws_raise_error(aws_err); } AWS_LOGF_DEBUG( @@ -1086,6 +1106,7 @@ static int s_ipv6_stream_connect( struct sockaddr_in6 addr_in6; int pton_err = inet_pton(AF_INET6, remote_endpoint->address, &(addr_in6.sin6_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call before logging or WSAError may get cleared */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: failed to parse address %s:%d.", @@ -1093,7 +1114,7 @@ static int s_ipv6_stream_connect( (void *)socket->io_handle.data.handle, remote_endpoint->address, (int)remote_endpoint->port); - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } AWS_LOGF_DEBUG( @@ -1223,18 +1244,20 @@ static inline int s_dgram_connect( int reuse = 1; if (setsockopt((SOCKET)socket->io_handle.data.handle, SOL_SOCKET, SO_REUSEADDR, (char *)&reuse, sizeof(int))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_WARN( AWS_LS_IO_SOCKET, "id=%p handle=%p: setsockopt() call for enabling SO_REUSEADDR failed with WSAError %d", (void *)socket, (void *)socket->io_handle.data.handle, - WSAGetLastError()); - return aws_raise_error(s_determine_socket_error(WSAGetLastError())); + wsa_err); + return aws_raise_error(s_determine_socket_error(wsa_err)); } int connect_err = connect((SOCKET)socket->io_handle.data.handle, socket_addr, (int)sock_size); if (connect_err) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: Failed to connect to %s:%d with error %d.", @@ -1242,10 +1265,9 @@ static inline int s_dgram_connect( (void *)socket->io_handle.data.handle, remote_endpoint->address, (int)remote_endpoint->port, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error_code = WSAGetLastError(); - int aws_error = s_determine_socket_error(error_code); + int aws_error = s_determine_socket_error(wsa_err); aws_raise_error(aws_error); socket_impl->vtable->connection_error(socket, aws_error); return AWS_OP_ERR; @@ -1284,14 +1306,15 @@ static inline int s_dgram_connect( } if (sock_name_err) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: Failed to connect with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); aws_raise_error(error); return AWS_OP_ERR; } @@ -1331,8 +1354,9 @@ static int s_ipv4_dgram_connect( struct sockaddr_in addr_in; int pton_err = inet_pton(AF_INET, remote_endpoint->address, &(addr_in.sin_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call right after failure, so that WSAError isn't cleared */ socket->state = ERRORED; - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } addr_in.sin_port = htons(remote_endpoint->port); @@ -1356,8 +1380,9 @@ static int s_ipv6_dgram_connect( int pton_err = inet_pton(AF_INET6, remote_endpoint->address, &(addr_in6.sin6_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call right after failure, so that WSAError isn't cleared */ socket->state = ERRORED; - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } addr_in6.sin6_port = htons(remote_endpoint->port); @@ -1389,13 +1414,14 @@ static inline int s_tcp_bind( SO_EXCLUSIVEADDRUSE, (char *)&exclusive_use_val, sizeof(int))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_WARN( AWS_LS_IO_SOCKET, "id=%p handle=%p: setsockopt() call for enabling SO_EXCLUSIVEADDRUSE failed with WSAError %d", (void *)socket, (void *)socket->io_handle.data.handle, - WSAGetLastError()); - int error = s_determine_socket_error(WSAGetLastError()); + wsa_err); + int error = s_determine_socket_error(wsa_err); return aws_raise_error(error); } @@ -1406,14 +1432,15 @@ static inline int s_tcp_bind( return AWS_OP_SUCCESS; } + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: error binding. error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); return aws_raise_error(error); } @@ -1422,8 +1449,9 @@ static int s_ipv4_stream_bind(struct aws_socket *socket, const struct aws_socket int pton_err = inet_pton(AF_INET, local_endpoint->address, &(addr_in.sin_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call right after failure, so that WSAError isn't cleared */ socket->state = ERRORED; - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } addr_in.sin_port = htons(local_endpoint->port); @@ -1437,8 +1465,9 @@ static int s_ipv6_stream_bind(struct aws_socket *socket, const struct aws_socket int pton_err = inet_pton(AF_INET6, local_endpoint->address, &(addr_in6.sin6_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call right after failure, so that WSAError isn't cleared */ socket->state = ERRORED; - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } addr_in6.sin6_port = htons(local_endpoint->port); @@ -1467,14 +1496,15 @@ static inline int s_udp_bind( return AWS_OP_SUCCESS; } + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: error binding. error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + wsa_err); socket->state = ERRORED; - int error = s_determine_socket_error(WSAGetLastError()); + int error = s_determine_socket_error(wsa_err); return aws_raise_error(error); } @@ -1483,8 +1513,9 @@ static int s_ipv4_dgram_bind(struct aws_socket *socket, const struct aws_socket_ int pton_err = inet_pton(AF_INET, local_endpoint->address, &(addr_in.sin_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call right after failure, so that WSAError isn't cleared */ socket->state = ERRORED; - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } addr_in.sin_port = htons(local_endpoint->port); @@ -1498,8 +1529,9 @@ static int s_ipv6_dgram_bind(struct aws_socket *socket, const struct aws_socket_ int pton_err = inet_pton(AF_INET6, local_endpoint->address, &(addr_in6.sin6_addr)); if (pton_err != 1) { + int aws_err = s_convert_pton_error(pton_err); /* call right after failure, so that WSAError isn't cleared */ socket->state = ERRORED; - return aws_raise_error(s_convert_pton_error(pton_err)); + return aws_raise_error(aws_err); } addr_in6.sin6_port = htons(local_endpoint->port); @@ -1825,7 +1857,7 @@ static int s_socket_setup_accept(struct aws_socket *socket, struct aws_event_loo "id=%p handle=%p: accept failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - (int)WSAGetLastError()); + (int)win_err); socket->state = ERRORED; socket_impl->read_io_data->in_use = false; aws_mem_release(socket->allocator, socket_impl->incoming_socket); @@ -2244,12 +2276,13 @@ int aws_socket_set_options(struct aws_socket *socket, const struct aws_socket_op SO_KEEPALIVE, (char *)&keep_alive, sizeof(int))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_WARN( AWS_LS_IO_SOCKET, "id=%p handle=%p: setsockopt() call for enabling keep-alive failed with WSAError %d", (void *)socket, (void *)socket->io_handle.data.handle, - WSAGetLastError()); + wsa_err); } } else if (socket->options.keepalive) { ULONG keep_alive_timeout = (ULONG)aws_timestamp_convert( @@ -2272,12 +2305,13 @@ int aws_socket_set_options(struct aws_socket *socket, const struct aws_socket_op &bytes_returned, NULL, NULL)) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_WARN( AWS_LS_IO_SOCKET, "id=%p handle=%p: WSAIoctl() call for setting keep-alive values failed with WSAError %d", (void *)socket, (void *)socket->io_handle.data.handle, - WSAGetLastError()); + wsa_err); } } /* this is only available in Windows 10 1703 and later. It doesn't, matter if this runs on an older version @@ -2291,6 +2325,7 @@ int aws_socket_set_options(struct aws_socket *socket, const struct aws_socket_op TCP_KEEPCNT, (char *)&max_probes, sizeof(max_probes))) { + int wsa_err = WSAGetLastError(); /* logging may reset error, so cache it */ AWS_LOGF_WARN( AWS_LS_IO_SOCKET, "id=%p handle=%p: setsockopt() call for setting keep-alive probe count value failed with WSAError " @@ -2299,7 +2334,7 @@ int aws_socket_set_options(struct aws_socket *socket, const struct aws_socket_op "Windows 10 1703", (void *)socket, (void *)socket->io_handle.data.handle, - WSAGetLastError()); + wsa_err); } } #endif @@ -2673,18 +2708,18 @@ static int s_stream_subscribe_to_read( NULL, aws_overlapped_to_windows_overlapped(&iocp_socket->read_io_data->signal)); if (!success) { - int wsa_err = WSAGetLastError(); - if (wsa_err != ERROR_IO_PENDING) { + int win_err = GetLastError(); + if (win_err != ERROR_IO_PENDING) { AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: socket ReadFile() failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - wsa_err); + win_err); iocp_socket->read_io_data->in_use = false; socket->state &= ~CONNECTED_WAITING_ON_READABLE; - int aws_error = s_determine_socket_error(wsa_err); + int aws_error = s_determine_socket_error(win_err); if (aws_error == AWS_IO_SOCKET_CLOSED) { socket->state = CLOSED; } else { @@ -2787,16 +2822,16 @@ static int s_local_read(struct aws_socket *socket, struct aws_byte_buf *buffer, NULL, aws_overlapped_to_windows_overlapped(&iocp_socket->read_io_data->signal)); if (!success) { - int wsa_err = GetLastError(); - if (wsa_err != ERROR_IO_PENDING) { + int win_err = GetLastError(); + if (win_err != ERROR_IO_PENDING) { AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: ReadFile() failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - wsa_err); + win_err); iocp_socket->read_io_data->in_use = false; - int aws_error = s_determine_socket_error(wsa_err); + int aws_error = s_determine_socket_error(win_err); if (aws_error == AWS_IO_SOCKET_CLOSED) { socket->state = CLOSED; } else { @@ -2911,16 +2946,16 @@ static int s_tcp_read(struct aws_socket *socket, struct aws_byte_buf *buffer, si NULL, aws_overlapped_to_windows_overlapped(&iocp_socket->read_io_data->signal)); if (!success) { - int wsa_err = GetLastError(); - if (wsa_err != ERROR_IO_PENDING) { + int win_err = GetLastError(); + if (win_err != ERROR_IO_PENDING) { AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, "id=%p handle=%p: ReadFile() for 0 byte read failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, - wsa_err); + win_err); iocp_socket->read_io_data->in_use = false; - int aws_error = s_determine_socket_error(wsa_err); + int aws_error = s_determine_socket_error(win_err); if (aws_error == AWS_IO_SOCKET_CLOSED) { socket->state = CLOSED; } else { @@ -3048,7 +3083,7 @@ static int s_dgram_read(struct aws_socket *socket, struct aws_byte_buf *buffer, AWS_LOGF_ERROR( AWS_LS_IO_SOCKET, - "id=%p handle=%p: ReadFile() failed with error %d", + "id=%p handle=%p: recv() failed with error %d", (void *)socket, (void *)socket->io_handle.data.handle, error);