US2035 add logs in replica for listed scenarios to debug volume read-…

…only cases (openzfs#80)

Feature for processing zfs ereports and other events and printing details
of them to stderr (log file).
Documenting ways of changing log level in various environments.

Signed-off-by: Jan Kryl <[email protected]>

.gitignore

@@ -21,6 +21,7 @@
 *.swp
 *.gcno
 *.gcda
+*.ur-safe
 .deps
 .libs
 .dirstamp

README.markdown

@@ -85,7 +85,7 @@ etc. Explanation of the two mounted volumes follows:
 ```bash
 sudo docker build -t my-cstor .
 sudo mkdir /tmp/cstor
-sudo docker run --privileged -it -v /dev:/dev --mount source=cstortmp,target=/tmp my-cstor
+sudo docker run --privileged -it -v /dev:/dev -v /run/udev:/run/udev --mount source=cstortmp,target=/tmp my-cstor
 sudo docker exec -it <container-id> /bin/bash
 ```
 
@@ -97,6 +97,30 @@ sudo docker build -t localhost:5000/my-cstor .
 sudo docker push localhost:5000/my-cstor
 ```
 
+# Troubleshooting
+
+In order to print debug messages start zrepl with `-l debug` argument. If
+running zrepl in container with standard entrypoint.sh script, set env
+variable LOGLEVEL=debug. To do the same when running zrepl on k8s cluster
+use patch command to insert the same env variable to pod definition.
+Details differ based on how zrepl container was deployed on k8s cluster:
+
+```bash
+kubectl patch deployment cstor-deployment-name --patch "$(cat patch.yaml)"
+```
+
+where patch.yaml content is:
+```
+spec:
+  template:
+    spec:
+      containers:
+      - name: cstor-container-name
+        env:
+        - name: LOGLEVEL
+          value: "debug"
+```
+
 # Caveats
 
 Disk write cache must be disabled for any device not managed by linux

cmd/zrepl/Makefile.am

@@ -13,7 +13,8 @@ DEFAULT_INCLUDES += \
 sbin_PROGRAMS = zrepl
 
 zrepl_SOURCES = \
-	zrepl.c
+	zrepl.c \
+	zfs_events.c
 
 zrepl_LDADD = \
 	$(top_builddir)/lib/libnvpair/libnvpair.la \

cmd/zrepl/zfs_events.c

@@ -0,0 +1,138 @@
+/*
+ * CDDL HEADER START
+ *
+ * The contents of this file are subject to the terms of the
+ * Common Development and Distribution License (the "License").
+ * You may not use this file except in compliance with the License.
+ *
+ * You can obtain a copy of the license at usr/src/OPENSOLARIS.LICENSE
+ * or http://www.opensolaris.org/os/licensing.
+ * See the License for the specific language governing permissions
+ * and limitations under the License.
+ *
+ * When distributing Covered Code, include this CDDL HEADER in each
+ * file and include the License file at usr/src/OPENSOLARIS.LICENSE.
+ * If applicable, add the following below this CDDL HEADER, with the
+ * fields enclosed by brackets "[]" replaced with your own identifying
+ * information: Portions Copyright [yyyy] [name of copyright owner]
+ *
+ * CDDL HEADER END
+ */
+/*
+ * Copyright (c) 2018 Cloudbyte. All rights reserved.
+ */
+
+#include <sys/fm/util.h>
+#include <sys/fm/protocol.h>
+#include <sys/fm/fs/zfs.h>
+#include <libzfs.h>
+#include <zrepl_mgmt.h>
+
+#include "zfs_events.h"
+
+/*
+ * Print vdev state change event in user friendly way.
+ */
+static void
+print_state_change(nvlist_t *event)
+{
+	char	*pool_name;
+	char	*vdev_name;
+	uint64_t new_state, old_state;
+
+	if (nvlist_lookup_string(event,
+	    FM_EREPORT_PAYLOAD_ZFS_POOL, &pool_name) != 0 ||
+	    nvlist_lookup_string(event,
+	    FM_EREPORT_PAYLOAD_ZFS_VDEV_PATH, &vdev_name) != 0 ||
+	    nvlist_lookup_uint64(event,
+	    FM_EREPORT_PAYLOAD_ZFS_VDEV_STATE, &new_state) != 0 ||
+	    nvlist_lookup_uint64(event,
+	    FM_EREPORT_PAYLOAD_ZFS_VDEV_LASTSTATE, &old_state) != 0) {
+		LOG_ERR("Invalid content of ZFS state change event");
+	} else {
+		LOG_INFO("Vdev %s in pool %s changed state: %s -> %s",
+		    vdev_name, pool_name,
+		    zpool_state_to_name(old_state, VDEV_AUX_NONE),
+		    zpool_state_to_name(new_state, VDEV_AUX_NONE));
+	}
+}
+
+/*
+ * Print the event in raw form to stderr.
+ */
+static void
+print_zfs_event(nvlist_t *event)
+{
+	enum zrepl_log_level lvl = LOG_LEVEL_ERR;
+	boolean_t skip = B_FALSE;
+	char	*class;
+
+	if (nvlist_lookup_string(event, FM_CLASS, &class) != 0) {
+		LOG_ERR("Missing class in zfs ereport");
+		nvlist_free(event);
+		return;
+	}
+
+	if (strcmp(class, FM_EREPORT_CLASS "." ZFS_ERROR_CLASS "."
+	    FM_EREPORT_ZFS_CONFIG_CACHE_WRITE) == 0) {
+		/*
+		 * This event is generated upon every spa configuration
+		 * change because zrepl does not have a cache file.
+		 */
+		skip = B_TRUE;
+	} else if (strcmp(class, FM_RSRC_RESOURCE "." ZFS_ERROR_CLASS "."
+	    FM_RESOURCE_REMOVED) == 0) {
+		lvl = LOG_LEVEL_INFO;
+	} else if (strcmp(class, FM_RSRC_RESOURCE "." ZFS_ERROR_CLASS "."
+	    FM_RESOURCE_AUTOREPLACE) == 0) {
+		lvl = LOG_LEVEL_INFO;
+	} else if (strcmp(class, FM_RSRC_RESOURCE "." ZFS_ERROR_CLASS "."
+	    FM_RESOURCE_STATECHANGE) == 0) {
+		print_state_change(event);
+		skip = B_TRUE;
+	}
+
+	if (!skip) {
+		zrepl_log(lvl, "ZFS event:");
+		fm_nvprint(event);
+	}
+	nvlist_free(event);
+}
+
+/*
+ * Endless loop in which we wait for new zfs events being generated and print
+ * them.
+ */
+void
+zrepl_monitor_errors(void)
+{
+	zfs_zevent_t	*ze;
+	nvlist_t	*event = NULL;
+	uint64_t	size, dropped;
+	int		rc;
+
+	zfs_zevent_init(&ze);
+
+	while (1) {
+		// There is no limit for event size because we are not going to
+		// copy it to a preallocated buffer
+		size = -1;
+		dropped = 0;
+		rc = zfs_zevent_next(ze, &event, &size, &dropped);
+		if (dropped > 0) {
+			LOG_ERR("Dropped %lu zfs events", dropped);
+		}
+		if (event != NULL) {
+			print_zfs_event(event);
+			event = NULL;
+		}
+		if (rc != 0) {
+			if (rc == ENOENT) {
+				zfs_zevent_wait(ze);
+			} else {
+				LOG_ERR("Failed to get zfs events: %d", rc);
+			}
+		}
+	}
+	zfs_zevent_destroy(ze);
+}

cmd/zrepl/zfs_events.h

@@ -0,0 +1,30 @@
+/*
+ * CDDL HEADER START
+ *
+ * The contents of this file are subject to the terms of the
+ * Common Development and Distribution License (the "License").
+ * You may not use this file except in compliance with the License.
+ *
+ * You can obtain a copy of the license at usr/src/OPENSOLARIS.LICENSE
+ * or http://www.opensolaris.org/os/licensing.
+ * See the License for the specific language governing permissions
+ * and limitations under the License.
+ *
+ * When distributing Covered Code, include this CDDL HEADER in each
+ * file and include the License file at usr/src/OPENSOLARIS.LICENSE.
+ * If applicable, add the following below this CDDL HEADER, with the
+ * fields enclosed by brackets "[]" replaced with your own identifying
+ * information: Portions Copyright [yyyy] [name of copyright owner]
+ *
+ * CDDL HEADER END
+ */
+/*
+ * Copyright (c) 2018 Cloudbyte. All rights reserved.
+ */
+
+#ifndef	ZFS_EVENTS_H
+#define	ZFS_EVENTS_H
+
+void zrepl_monitor_errors(void);
+
+#endif	/* ZFS_EVENTS_H */

cmd/zrepl/zrepl.c

@@ -14,9 +14,10 @@
 #include <uzfs_rebuilding.h>
 #include <atomic.h>
 #include <uzfs_zap.h>
+#include <mgmt_conn.h>
+#include <data_conn.h>
 
-#include "mgmt_conn.h"
-#include "data_conn.h"
+#include "zfs_events.h"
 
 #define	ZAP_UPDATE_TIME_INTERVAL 2
 
@@ -171,30 +172,33 @@ uzfs_zvol_io_receiver(void *arg)
 
 	/* First command should be OPEN */
 	while (zinfo == NULL) {
-		if (open_zvol(fd, &zinfo) != 0)
-			goto exit;
+		if (open_zvol(fd, &zinfo) != 0) {
+			shutdown(fd, SHUT_RDWR);
+			(void) close(fd);
+			LOG_INFO("Data connection closed");
+			zk_thread_exit();
+			return;
+		}
 	}
+	LOG_INFO("Data connection associated with zvol %s", zinfo->name);
 
-	while (1) {
-		rc = uzfs_zvol_socket_read(fd, (char *)&hdr,
-		    sizeof (hdr));
-		if (rc != 0)
-			goto exit;
+	while ((rc = uzfs_zvol_socket_read(fd, (char *)&hdr, sizeof (hdr))) ==
+	    0) {
 
 		if (hdr.opcode != ZVOL_OPCODE_WRITE &&
 		    hdr.opcode != ZVOL_OPCODE_READ &&
 		    hdr.opcode != ZVOL_OPCODE_SYNC) {
 			LOG_ERR("Unexpected opcode %d", hdr.opcode);
-			goto exit;
+			break;
 		}
 
 		if (((hdr.opcode == ZVOL_OPCODE_WRITE) ||
 		    (hdr.opcode == ZVOL_OPCODE_READ)) && !hdr.len) {
 			LOG_ERR("Zero Payload size for opcode %d", hdr.opcode);
-			goto exit;
+			break;
 		} else if ((hdr.opcode == ZVOL_OPCODE_SYNC) && hdr.len > 0) {
 			LOG_ERR("Unexpected payload for opcode %d", hdr.opcode);
-			goto exit;
+			break;
 		}
 
 		zio_cmd = zio_cmd_alloc(&hdr, fd);
@@ -203,7 +207,7 @@ uzfs_zvol_io_receiver(void *arg)
 			rc = uzfs_zvol_socket_read(fd, zio_cmd->buf, hdr.len);
 			if (rc != 0) {
 				zio_cmd_free(&zio_cmd);
-				goto exit;
+				break;
 			}
 		}
 
@@ -213,33 +217,27 @@ uzfs_zvol_io_receiver(void *arg)
 		taskq_dispatch(zinfo->uzfs_zvol_taskq, uzfs_zvol_worker,
 		    zio_cmd, TQ_SLEEP);
 	}
-exit:
-	if (zinfo != NULL) {
-		LOG_DEBUG("uzfs_zvol_io_receiver thread for zvol %s exiting",
-		    zinfo->name);
-		(void) pthread_mutex_lock(&zinfo->zinfo_mutex);
-		zinfo->conn_closed = B_TRUE;
-		/*
-		 * Send signal to ack sender so that it can free
-		 * zio_cmd, close fd and exit.
-		 */
-		if (zinfo->io_ack_waiting) {
-			rc = pthread_cond_signal(&zinfo->io_ack_cond);
-		}
-		/*
-		 * wait for ack thread to exit to avoid races with new
-		 * connections for the same zinfo
-		 */
-		while (zinfo->conn_closed && zinfo->is_io_ack_sender_created) {
-			(void) pthread_mutex_unlock(&zinfo->zinfo_mutex);
-			usleep(1000);
-			(void) pthread_mutex_lock(&zinfo->zinfo_mutex);
-		}
+
+	(void) pthread_mutex_lock(&zinfo->zinfo_mutex);
+	zinfo->conn_closed = B_TRUE;
+	/*
+	 * Send signal to ack sender so that it can free
+	 * zio_cmd, close fd and exit.
+	 */
+	if (zinfo->io_ack_waiting) {
+		rc = pthread_cond_signal(&zinfo->io_ack_cond);
+	}
+	/*
+	 * wait for ack thread to exit to avoid races with new
+	 * connections for the same zinfo
+	 */
+	while (zinfo->conn_closed && zinfo->is_io_ack_sender_created) {
 		(void) pthread_mutex_unlock(&zinfo->zinfo_mutex);
-		uzfs_zinfo_drop_refcnt(zinfo, B_FALSE);
-	} else {
-		LOG_DEBUG("uzfs_zvol_io_receiver thread exiting");
+		usleep(1000);
+		(void) pthread_mutex_lock(&zinfo->zinfo_mutex);
 	}
+	(void) pthread_mutex_unlock(&zinfo->zinfo_mutex);
+	uzfs_zinfo_drop_refcnt(zinfo, B_FALSE);
 	zk_thread_exit();
 }
 
@@ -413,12 +411,10 @@ uzfs_zvol_io_ack_sender(void *arg)
 		zio_cmd_free(&zio_cmd);
 	}
 exit:
-	LOG_DEBUG("uzfs_zvol_io_ack_sender thread for zvol %s exiting",
-	    zinfo->name);
-
 	zinfo->zio_cmd_in_ack = NULL;
 	shutdown(fd, SHUT_RDWR);
 	close(fd);
+	LOG_INFO("Data connection for zvol %s closed", zinfo->name);
 	while (!STAILQ_EMPTY(&zinfo->complete_queue)) {
 		zio_cmd = STAILQ_FIRST(&zinfo->complete_queue);
 		STAILQ_REMOVE_HEAD(&zinfo->complete_queue, cmd_link);
@@ -558,9 +554,7 @@ main(int argc, char **argv)
 	}
 
 	zrepl_svc_run();
-	while (1) {
-		sleep(5);
-	}
+	zrepl_monitor_errors();
 
 initialize_error:
 	uzfs_fini();