CDRIVER-756: Improve debugging

Check return codes using <=
Return how much we have written, even if the last vector wasn't even tried
Plentyful traces
Disable IO dumping

Author: bjori

src/mongoc/mongoc-socket.c

@@ -931,6 +931,7 @@ _mongoc_socket_try_sendv (mongoc_socket_t *sock,   /* IN */
 # endif
 #endif
 
+   TRACE("Send %ld out of %ld bytes (errno=%d)", ret, iov->iov_len, errno);
    /*
     * Check to see if we have sent an iovec too large for sendmsg to
     * complete. If so, we need to fallback to the slow path of multiple
@@ -995,6 +996,7 @@ mongoc_socket_sendv (mongoc_socket_t  *sock,      /* IN */
 
    for (;;) {
       sent = _mongoc_socket_try_sendv (sock, &iov [cur], iovcnt - cur);
+      TRACE("Sent %ld (of %ld) out of iovcnt=%ld", sent, iov[cur].iov_len, iovcnt);
 
       /*
        * If we failed with anything other than EAGAIN or EWOULDBLOCK,
@@ -1004,7 +1006,7 @@ mongoc_socket_sendv (mongoc_socket_t  *sock,      /* IN */
       if (sent == -1) {
          if (!_mongoc_socket_errno_is_again (sock)) {
             ret = -1;
-            goto CLEANUP;
+            GOTO(CLEANUP);
          }
       }
 
@@ -1019,6 +1021,7 @@ mongoc_socket_sendv (mongoc_socket_t  *sock,      /* IN */
           * Subtract the sent amount from what we still need to send.
           */
          while ((cur < iovcnt) && (sent >= (ssize_t)iov [cur].iov_len)) {
+            TRACE("still got bytes left: sent -= iov_len: %ld -= %ld", sent, iov[cur+1].iov_len);
             sent -= iov [cur++].iov_len;
          }
 
@@ -1027,27 +1030,31 @@ mongoc_socket_sendv (mongoc_socket_t  *sock,      /* IN */
           * sending data over the socket.
           */
          if (cur == iovcnt) {
+            TRACE("%s", "Finished the iovecs");
             break;
          }
 
          /*
           * Increment the current iovec buffer to its proper offset and adjust
           * the number of bytes to write.
           */
+         TRACE("Seeked io_base+%ld", sent);
+         TRACE("Subtracting iov_len -= sent; %ld -= %ld", iov[cur].iov_len, sent);
          iov [cur].iov_base = ((char *)iov [cur].iov_base) + sent;
          iov [cur].iov_len -= sent;
+         TRACE("iov_len remaining %ld", iov[cur].iov_len);
 
          BSON_ASSERT (iovcnt - cur);
          BSON_ASSERT (iov [cur].iov_len);
       } else if (OPERATION_EXPIRED (expire_at)) {
-         goto CLEANUP;
+         GOTO(CLEANUP);
       }
 
       /*
        * Block on poll() until our desired condition is met.
        */
       if (!_mongoc_socket_wait (sock->sd, POLLOUT, expire_at)) {
-         goto CLEANUP;
+         GOTO(CLEANUP);
       }
    }
 

src/mongoc/mongoc-stream-tls.c

@@ -205,9 +205,10 @@ _mongoc_stream_tls_bio_read (BIO  *b,
 
    BSON_ASSERT (b);
    BSON_ASSERT (buf);
+   ENTRY;
 
    if (!(tls = b->ptr)) {
-      return -1;
+      RETURN (-1);
    }
 
    errno = 0;
@@ -216,10 +217,11 @@ _mongoc_stream_tls_bio_read (BIO  *b,
    BIO_clear_retry_flags (b);
 
    if ((ret < 0) && MONGOC_ERRNO_IS_AGAIN (errno)) {
+      MONGOC_DEBUG("set_retry_read");
       BIO_set_retry_read (b);
    }
 
-   return ret;
+   RETURN (ret);
 }
 
 
@@ -247,27 +249,36 @@ _mongoc_stream_tls_bio_write (BIO        *b,
    mongoc_stream_tls_t *tls;
    mongoc_iovec_t iov;
    int ret;
+   ENTRY;
 
    BSON_ASSERT (b);
    BSON_ASSERT (buf);
 
    if (!(tls = b->ptr)) {
-      return -1;
+      RETURN (-1);
    }
 
    iov.iov_base = (void *)buf;
    iov.iov_len = len;
 
    errno = 0;
+   TRACE("mongoc_stream_writev is expected to write: %d", len);
    ret = (int)mongoc_stream_writev (tls->base_stream, &iov, 1,
                                     tls->timeout_msec);
    BIO_clear_retry_flags (b);
 
-   if ((ret < 0) && MONGOC_ERRNO_IS_AGAIN (errno)) {
+   if (len > ret) {
+      TRACE("Returned short write: %d of %d", ret, len);
+   } else {
+      TRACE("Completed the %d", ret);
+   }
+   if (ret <= 0 && MONGOC_ERRNO_IS_AGAIN (errno)) {
+      TRACE("%s", "Requesting a retry");
       BIO_set_retry_write (b);
    }
 
-   return ret;
+
+   RETURN (ret);
 }
 
 
@@ -416,10 +427,13 @@ static int
 _mongoc_stream_tls_close (mongoc_stream_t *stream)
 {
    mongoc_stream_tls_t *tls = (mongoc_stream_tls_t *)stream;
+   int ret = 0;
+   ENTRY;
 
    BSON_ASSERT (tls);
 
-   return mongoc_stream_close (tls->base_stream);
+   ret = mongoc_stream_close (tls->base_stream);
+   RETURN (ret);
 }
 
 
@@ -459,6 +473,7 @@ _mongoc_stream_tls_write (mongoc_stream_tls_t *tls,
 
    int64_t now;
    int64_t expire = 0;
+   ENTRY;
 
    BSON_ASSERT (tls);
    BSON_ASSERT (buf);
@@ -469,8 +484,10 @@ _mongoc_stream_tls_write (mongoc_stream_tls_t *tls,
    }
 
    ret = BIO_write (tls->bio, buf, buf_len);
+   TRACE("BIO_write returned %ld", ret);
 
-   if (ret < 0) {
+   TRACE("I got ret: %ld and retry: %d", ret, BIO_should_retry (tls->bio));
+   if (ret <= 0) {
       return ret;
    }
 
@@ -488,7 +505,13 @@ _mongoc_stream_tls_write (mongoc_stream_tls_t *tls,
       }
    }
 
-   return ret;
+   if (ret <= 0 && BIO_should_retry (tls->bio)) {
+      if (tls->timeout_msec > 0) {
+         TRACE("I do have %dmsec left", tls->timeout_msec);
+      }
+   }
+
+   RETURN (ret);
 }
 
 
@@ -545,6 +568,7 @@ _mongoc_stream_tls_writev (mongoc_stream_t *stream,
    BSON_ASSERT (tls);
    BSON_ASSERT (iov);
    BSON_ASSERT (iovcnt);
+   ENTRY;
 
    tls->timeout_msec = timeout_msec;
 
@@ -590,18 +614,23 @@ _mongoc_stream_tls_writev (mongoc_stream_t *stream,
              * if we didn't buffer and have to send out of the iovec */
 
             child_ret = _mongoc_stream_tls_write (tls, to_write, to_write_len);
+            if (child_ret != to_write_len) {
+               MONGOC_DEBUG("Got child_ret: %ld while to_write_len is: %ld",
+                     child_ret, to_write_len);
+            }
 
             if (child_ret < 0) {
                /* Buffer write failed, just return the error */
-               return child_ret;
+               TRACE("Returning what I had: %ld", ret);
+               RETURN (ret);
             }
 
             ret += child_ret;
 
             if (child_ret < to_write_len) {
                /* we timed out, so send back what we could send */
 
-               return ret;
+               RETURN (ret);
             }
 
             to_write = NULL;
@@ -612,10 +641,12 @@ _mongoc_stream_tls_writev (mongoc_stream_t *stream,
    if (buf_head != buf_tail) {
       /* If we have any bytes buffered, send */
 
+      TRACE("buffered writing %ld", buf_tail - buf_head);
       child_ret = _mongoc_stream_tls_write (tls, buf_head, buf_tail - buf_head);
+      TRACE("Got %ld written", child_ret);
 
       if (child_ret < 0) {
-         return child_ret;
+         RETURN (child_ret);
       }
 
       ret += child_ret;
@@ -625,7 +656,7 @@ _mongoc_stream_tls_writev (mongoc_stream_t *stream,
       mongoc_counter_streams_egress_add (ret);
    }
 
-   return ret;
+   RETURN (ret);
 }
 
 
@@ -661,6 +692,7 @@ _mongoc_stream_tls_readv (mongoc_stream_t *stream,
    size_t iov_pos = 0;
    int64_t now;
    int64_t expire = 0;
+   ENTRY;
 
    BSON_ASSERT (tls);
    BSON_ASSERT (iov);
@@ -702,7 +734,7 @@ _mongoc_stream_tls_readv (mongoc_stream_t *stream,
 #else
                   errno = ETIMEDOUT;
 #endif
-                  return -1;
+                  RETURN (-1);
                }
 
                tls->timeout_msec = 0;
@@ -715,7 +747,7 @@ _mongoc_stream_tls_readv (mongoc_stream_t *stream,
 
          if ((size_t)ret >= min_bytes) {
             mongoc_counter_streams_ingress_add(ret);
-            return ret;
+            RETURN (ret);
          }
 
          iov_pos += read_ret;
@@ -726,7 +758,7 @@ _mongoc_stream_tls_readv (mongoc_stream_t *stream,
       mongoc_counter_streams_ingress_add(ret);
    }
 
-   return ret;
+   RETURN (ret);
 }
 
 

src/mongoc/mongoc-stream.c

@@ -306,12 +306,14 @@ _mongoc_stream_writev_full (mongoc_stream_t *stream,
    size_t total_bytes = 0;
    int i;
    ssize_t r;
+   ENTRY;
 
    for (i = 0; i < iovcnt; i++) {
       total_bytes += iov[i].iov_len;
    }
 
    r = mongoc_stream_writev(stream, iov, iovcnt, timeout_msec);
+   TRACE("writev returned: %d", r);
 
    if (r < 0) {
       if (error) {
@@ -324,16 +326,16 @@ _mongoc_stream_writev_full (mongoc_stream_t *stream,
                          "Failure during socket delivery: %s", errstr);
       }
 
-      return false;
+      RETURN(false);
    }
 
    if (r != total_bytes) {
       bson_set_error (error, MONGOC_ERROR_STREAM, MONGOC_ERROR_STREAM_SOCKET,
                       "Failure to send all requested bytes (only sent: %ld/%ld in %dms) during socket delivery",
                       (int64_t)r, (int64_t)total_bytes, timeout_msec);
 
-      return false;
+      RETURN(false);
    }
 
-   return true;
+   RETURN(true);
 }

src/mongoc/mongoc-trace.h

@@ -40,6 +40,7 @@ BSON_BEGIN_DECLS
       bson_string_t *str, *astr; \
       int32_t _i; \
       uint8_t _v; \
+      break; \
       mongoc_log(MONGOC_LOG_LEVEL_TRACE, MONGOC_LOG_DOMAIN, \
                  " %s = %p [%d]", #_n, _b, (int)_l); \
       str = bson_string_new(NULL); \
@@ -81,6 +82,7 @@ BSON_BEGIN_DECLS
       unsigned _k = 0; \
       size_t _l = 0; \
       uint8_t _v; \
+      break; \
       for (_i = 0; _i < _iovcnt; _i++) { \
          _l += _iov[_i].iov_len; \
       } \