fuse: degrade logging of write failure to fuse device

Problem:

FUSE uses failures of communicating with /dev/fuse with various
errnos to indicate in-kernel conditions to userspace. Some of these
shouldn't be handled as an application error. Also the standard
POSIX errno description should not be shown as they are misleading
in this context.

Solution:

When writing to the fuse device, the caller of the respective
convenience routine can mask those errnos which don't qualify to
be an error for the application in that context, so then those
shall be reported at DEBUG level.

The possible non-standard errnos are reported with their
POSIX name instead of their description to avoid confusion.
(Eg. for ENOENT we don't log "no such file or directory",
we log indeed literal "ENOENT".)

Change-Id: I510158843e4b1d482bdc496c2e97b1860dc1ba93
>updates: bz#1193929
updates: #1000
Signed-off-by: Csaba Henk <csaba@redhat.com>
(cherry picked from commit 1166df1920dd9b2bd5fce53ab49d27117db40238)

2 files changed, 80 insertions, 7 deletions

diff --git a/xlators/mount/fuse/src/fuse-bridge.c b/xlators/mount/fuse/src/fuse-bridge.c
index c1020321bf9..17379182d68 100644
--- a/xlators/mount/fuse/src/fuse-bridge.c
+++ b/xlators/mount/fuse/src/fuse-bridge.c
@@ -205,7 +205,7 @@ fusedump_setup_meta(struct iovec *iovs, char *dir,
 
 static int
 check_and_dump_fuse_W(fuse_private_t *priv, struct iovec *iov_out, int count,
-                      ssize_t res)
+                      ssize_t res, errnomask_t errnomask)
 {
     char w = 'W';
     struct iovec diov[4] = {
@@ -223,8 +223,59 @@ check_and_dump_fuse_W(fuse_private_t *priv, struct iovec *iov_out, int count,
     struct fuse_out_header *fouh = NULL;
 
     if (res == -1) {
-        gf_log_callingfn("glusterfs-fuse", GF_LOG_ERROR,
-                         "writing to fuse device failed: %s", strerror(errno));
+        const char *errdesc = NULL;
+        gf_loglevel_t loglevel = GF_LOG_ERROR;
+
+        /* If caller masked the errno, then it
+         * does not indicate an error at the application
+         * level, so we degrade the log severity to DEBUG.
+         */
+        if (errnomask && errno < ERRNOMASK_MAX &&
+            GET_ERRNO_MASK(errnomask, errno))
+            loglevel = GF_LOG_DEBUG;
+
+        switch (errno) {
+            /* The listed errnos are FUSE status indicators,
+             * not legit values according to POSIX (see write(3p)),
+             * so resolving them according to the standard
+             * POSIX interpretation would be misleading.
+             */
+            case ENOENT:
+                errdesc = "ENOENT";
+                break;
+            case ENOTDIR:
+                errdesc = "ENOTDIR";
+                break;
+            case ENODEV:
+                errdesc = "ENODEV";
+                break;
+            case EPERM:
+                errdesc = "EPERM";
+                break;
+            case ENOMEM:
+                errdesc = "ENOMEM";
+                break;
+            case ENOTCONN:
+                errdesc = "ENOTCONN";
+                break;
+            case ECONNREFUSED:
+                errdesc = "ECONNREFUSED";
+                break;
+            case EOVERFLOW:
+                errdesc = "EOVERFLOW";
+                break;
+            case EBUSY:
+                errdesc = "EBUSY";
+                break;
+            case ENOTEMPTY:
+                errdesc = "ENOTEMPTY";
+                break;
+            default:
+                errdesc = strerror(errno);
+        }
+
+        gf_log_callingfn("glusterfs-fuse", loglevel,
+                         "writing to fuse device failed: %s", errdesc);
         return errno;
     }
 
@@ -289,7 +340,7 @@ send_fuse_iov(xlator_t *this, fuse_in_header_t *finh, struct iovec *iov_out,
     gf_log("glusterfs-fuse", GF_LOG_TRACE, "writev() result %d/%d %s", res,
            fouh->len, res == -1 ? strerror(errno) : "");
 
-    return check_and_dump_fuse_W(priv, iov_out, count, res);
+    return check_and_dump_fuse_W(priv, iov_out, count, res, NULL);
 }
 
 static int
@@ -355,6 +406,15 @@ fuse_invalidate_entry(xlator_t *this, uint64_t fuse_ino)
         fouh->unique = 0;
         fouh->error = FUSE_NOTIFY_INVAL_ENTRY;
 
+        if (ENOENT < ERRNOMASK_MAX)
+            MASK_ERRNO(node->errnomask, ENOENT);
+        if (ENOTDIR < ERRNOMASK_MAX)
+            MASK_ERRNO(node->errnomask, ENOTDIR);
+        if (EBUSY < ERRNOMASK_MAX)
+            MASK_ERRNO(node->errnomask, EBUSY);
+        if (ENOTEMPTY < ERRNOMASK_MAX)
+            MASK_ERRNO(node->errnomask, ENOTEMPTY);
+
         if (dentry->name) {
             nlen = strlen(dentry->name);
             fouh->len = sizeof(*fouh) + sizeof(*fnieo) + nlen + 1;
@@ -433,6 +493,9 @@ fuse_invalidate_inode(xlator_t *this, uint64_t fuse_ino)
     fniio->off = 0;
     fniio->len = -1;
 
+    if (ENOENT < ERRNOMASK_MAX)
+        MASK_ERRNO(node->errnomask, ENOENT);
+
     fuse_log_eh(this, "Invalidated inode %" PRIu64 " (gfid: %s)", fuse_ino,
                 uuid_utoa(inode->gfid));
     gf_log("glusterfs-fuse", GF_LOG_TRACE,
@@ -476,6 +539,7 @@ fuse_timed_message_new(void)
     /* should be NULL if not set */
     dmsg->fuse_message_body = NULL;
     INIT_LIST_HEAD(&dmsg->next);
+    memset(dmsg->errnomask, 0, sizeof(dmsg->errnomask));
 
     return dmsg;
 }
@@ -674,6 +738,8 @@ fuse_interrupt(xlator_t *this, fuse_in_header_t *finh, void *msg,
         dmsg->fuse_out_header.unique = finh->unique;
         dmsg->fuse_out_header.len = sizeof(dmsg->fuse_out_header);
         dmsg->fuse_out_header.error = -EAGAIN;
+        if (ENOENT < ERRNOMASK_MAX)
+            MASK_ERRNO(dmsg->errnomask, ENOENT);
         timespec_now(&dmsg->scheduled_ts);
         timespec_adjust_delta(&dmsg->scheduled_ts,
                               (struct timespec){0, 10000000});
@@ -4852,7 +4918,7 @@ notify_kernel_loop(void *data)
         iov_out.iov_base = node->inval_buf;
         iov_out.iov_len = len;
         rv = sys_writev(priv->fd, &iov_out, 1);
-        check_and_dump_fuse_W(priv, &iov_out, 1, rv);
+        check_and_dump_fuse_W(priv, &iov_out, 1, rv, node->errnomask);
 
         GF_FREE(node);
 
@@ -4943,7 +5009,7 @@ timed_response_loop(void *data)
         iovs[1] = (struct iovec){dmsg->fuse_message_body,
                                  len - sizeof(struct fuse_out_header)};
         rv = sys_writev(priv->fd, iovs, 2);
-        check_and_dump_fuse_W(priv, iovs, 2, rv);
+        check_and_dump_fuse_W(priv, iovs, 2, rv, dmsg->errnomask);
 
         fuse_timed_message_free(dmsg);
 
diff --git a/xlators/mount/fuse/src/fuse-bridge.h b/xlators/mount/fuse/src/fuse-bridge.h
index 697bd8848e1..06ed639bbcf 100644
--- a/xlators/mount/fuse/src/fuse-bridge.h
+++ b/xlators/mount/fuse/src/fuse-bridge.h
@@ -194,14 +194,20 @@ struct fuse_private {
 };
 typedef struct fuse_private fuse_private_t;
 
+typedef uint64_t errnomask_t[2];
+#define MASK_ERRNO(mask, n) ((mask)[(n) >> 6] |= ((uint64_t)1 << ((n)&63)))
+#define GET_ERRNO_MASK(mask, n) ((mask)[(n) >> 6] & ((uint64_t)1 << ((n)&63)))
+#define ERRNOMASK_MAX (64 * (sizeof(errnomask_t) / sizeof(uint64_t)))
+
 #define INVAL_BUF_SIZE                                                         \
     (sizeof(struct fuse_out_header) +                                          \
      max(sizeof(struct fuse_notify_inval_inode_out),                           \
          sizeof(struct fuse_notify_inval_entry_out) + NAME_MAX + 1))
 
 struct fuse_invalidate_node {
-    char inval_buf[INVAL_BUF_SIZE];
+    errnomask_t errnomask;
     struct list_head next;
+    char inval_buf[INVAL_BUF_SIZE];
 };
 typedef struct fuse_invalidate_node fuse_invalidate_node_t;
 
@@ -209,6 +215,7 @@ struct fuse_timed_message {
     struct fuse_out_header fuse_out_header;
     void *fuse_message_body;
     struct timespec scheduled_ts;
+    errnomask_t errnomask;
     struct list_head next;
 };
 typedef struct fuse_timed_message fuse_timed_message_t;