From f4a98dcc05ef7dde5cbdda729fa1c852a0efd2bc Mon Sep 17 00:00:00 2001 From: Jan Kryl Date: Mon, 4 Jun 2018 13:36:02 +0200 Subject: [PATCH] US1541 Debugging and logging at cStor target (#54) Signed-off-by: Jan Kryl --- cmd/zrepl/Makefile.am | 3 +- cmd/zrepl/data_conn.c | 39 +++++---- cmd/zrepl/mgmt_conn.c | 79 +++++++---------- cmd/zrepl/zrepl.c | 154 +++++++++++++++------------------ include/zrepl_mgmt.h | 40 +++++---- lib/libzpool/uzfs_mgmt.c | 17 ++-- lib/libzpool/uzfs_rebuilding.c | 14 +-- lib/libzpool/zrepl_mgmt.c | 66 ++++++++++---- 8 files changed, 207 insertions(+), 205 deletions(-) diff --git a/cmd/zrepl/Makefile.am b/cmd/zrepl/Makefile.am index bf704521036d..406fa8e4581a 100644 --- a/cmd/zrepl/Makefile.am +++ b/cmd/zrepl/Makefile.am @@ -2,8 +2,7 @@ include $(top_srcdir)/config/Rules.am # -Wnoformat-truncation to get rid of compiler warning for unchecked # truncating snprintfs on gcc 7.1.1. -AM_CFLAGS += $(DEBUG_STACKFLAGS) $(FRAME_LARGER_THAN) $(NO_FORMAT_TRUNCATION) -AM_CPPFLAGS += -DDEBUG +AM_CFLAGS += $(FRAME_LARGER_THAN) $(NO_FORMAT_TRUNCATION) DEFAULT_INCLUDES += \ -I$(top_srcdir)/include \ diff --git a/cmd/zrepl/data_conn.c b/cmd/zrepl/data_conn.c index 04a8d2d23981..c86645ece8da 100644 --- a/cmd/zrepl/data_conn.c +++ b/cmd/zrepl/data_conn.c @@ -99,7 +99,11 @@ uzfs_zvol_socket_read(int fd, char *buf, uint64_t nbytes) while (nbytes) { count = read(fd, (void *)p, nbytes); if (count <= 0) { - ZREPL_ERRLOG("Read error:%d\n", errno); + if (count == 0) { + LOG_INFO("Connection closed"); + } else { + LOG_ERRNO("Socket read error"); + } return (-1); } p += count; @@ -116,7 +120,11 @@ uzfs_zvol_socket_write(int fd, char *buf, uint64_t nbytes) while (nbytes) { count = write(fd, (void *)p, nbytes); if (count <= 0) { - ZREPL_ERRLOG("Write error:%d\n", errno); + if (count == 0) { + LOG_INFO("Connection closed"); + } else { + LOG_ERRNO("Socket write error"); + } return (-1); } p += count; @@ -233,8 +241,7 @@ uzfs_zvol_worker(void *arg) } if (rc != 0) { - ZREPL_ERRLOG("Zvol op_code :%d failed with " - "error: %d\n", hdr->opcode, errno); + LOG_ERR("OP code %d failed", hdr->opcode); hdr->status = ZVOL_OP_STATUS_FAILED; hdr->len = 0; } else { @@ -311,14 +318,14 @@ uzfs_zvol_rebuild_dw_replica(void *arg) rc = uzfs_zvol_socket_write(sfd, (char *)&hdr, sizeof (hdr)); if (rc == -1) { - ZREPL_ERRLOG("Socket write failed, err: %d\n", errno); + LOG_ERRNO("Socket write failed"); goto exit; } rc = uzfs_zvol_socket_write(sfd, (void *)rebuild_args->zvol_name, hdr.len); if (rc == -1) { - ZREPL_ERRLOG("Socket write failed, err: %d\n", errno); + LOG_ERRNO("Socket write failed"); goto exit; } @@ -332,7 +339,7 @@ uzfs_zvol_rebuild_dw_replica(void *arg) hdr.opcode = ZVOL_OPCODE_REBUILD_COMPLETE; rc = uzfs_zvol_socket_write(sfd, (char *)&hdr, sizeof (hdr)); if (rc != 0) { - ZREPL_ERRLOG("Socket write failed, err: %d\n", errno); + LOG_ERRNO("Socket write failed"); goto exit; } @@ -345,8 +352,7 @@ uzfs_zvol_rebuild_dw_replica(void *arg) uzfs_zvol_set_status(zinfo->zv, ZVOL_STATUS_HEALTHY); uzfs_update_ionum_interval(zinfo, 0); } - ZREPL_ERRLOG("Rebuilding on Replica:%s completed\n", - zinfo->name); + LOG_INFO("Rebuilding zvol %s completed", zinfo->name); goto exit; } else { bzero(&hdr, sizeof (hdr)); @@ -358,7 +364,7 @@ uzfs_zvol_rebuild_dw_replica(void *arg) hdr.len = ZVOL_REBUILD_STEP_SIZE; rc = uzfs_zvol_socket_write(sfd, (char *)&hdr, sizeof (hdr)); if (rc != 0) { - ZREPL_ERRLOG("Socket write failed, err: %d\n", errno); + LOG_ERRNO("Socket write failed"); goto exit; } } @@ -371,13 +377,13 @@ uzfs_zvol_rebuild_dw_replica(void *arg) rc = uzfs_zvol_socket_read(sfd, (char *)&hdr, sizeof (hdr)); if (rc != 0) { - ZREPL_ERRLOG("Socket read failed, err: %d\n", errno); + LOG_ERRNO("Socket read failed"); goto exit; } if (hdr.opcode == ZVOL_OPCODE_REBUILD_STEP_DONE) { offset += ZVOL_REBUILD_STEP_SIZE; - printf("ZVOL_OPCODE_REBUILD_STEP_DONE received\n"); + LOG_DEBUG("ZVOL_OPCODE_REBUILD_STEP_DONE received"); goto next_step; } @@ -388,8 +394,7 @@ uzfs_zvol_rebuild_dw_replica(void *arg) zio_cmd = zio_cmd_alloc(&hdr, sfd); rc = uzfs_zvol_socket_read(sfd, zio_cmd->buf, hdr.len); if (rc != 0) { - ZREPL_ERRLOG("Socket read failed with " - "error: %d\n", errno); + LOG_ERRNO("Socket read failed"); goto exit; } @@ -413,7 +418,7 @@ uzfs_zvol_rebuild_dw_replica(void *arg) if (rc == -1) uzfs_zvol_set_rebuild_status(zinfo->zv, ZVOL_REBUILDING_FAILED); - ZREPL_LOG("uzfs_zvol_rebuild_dw_replica thread exiting, volume:%s\n", + LOG_DEBUG("uzfs_zvol_rebuild_dw_replica thread exiting, zvol: %s", zinfo->name); /* Parent thread have taken refcount, drop it now */ uzfs_zinfo_drop_refcnt(zinfo, B_FALSE); @@ -443,8 +448,8 @@ uzfs_zvol_timer_thread(void) next_check = zinfo->checkpointed_time + zinfo->update_ionum_interval; if (next_check <= now) { - fprintf(stderr, "Checkpointing ionum " - "%lu on %s\n", + LOG_DEBUG("Checkpointing ionum " + "%lu on %s", zinfo->checkpointed_ionum, zinfo->name); uzfs_zvol_store_last_committed_io_no( diff --git a/cmd/zrepl/mgmt_conn.c b/cmd/zrepl/mgmt_conn.c index b7cda82965d9..fbf0942c88c4 100644 --- a/cmd/zrepl/mgmt_conn.c +++ b/cmd/zrepl/mgmt_conn.c @@ -63,33 +63,9 @@ * their state. */ -/* To print verbose debug messages uncomment the following line */ -#define MGMT_CONN_DEBUG 1 - -#ifdef MGMT_CONN_DEBUG -static const char * -gettimestamp(void) -{ - struct timeval tv; - static char buf[20]; - struct tm *timeinfo; - unsigned int ms; - - gettimeofday(&tv, NULL); - timeinfo = localtime(&tv.tv_sec); - ms = tv.tv_usec / 1000; - - strftime(buf, sizeof (buf), "%H:%M:%S.", timeinfo); - snprintf(buf + 9, sizeof (buf) - 9, "%u", ms); - - return (buf); -} -#define DBGCONN(c, fmt, ...) fprintf(stderr, "%s [tgt %s:%u]: " fmt "\n", \ - gettimestamp(), \ +/* LOG_DEBUG wrapper which puts target address prefix to message */ +#define DBGCONN(c, fmt, ...) LOG_DEBUG("[tgt %s:%u]: " fmt, \ (c)->conn_host, (c)->conn_port, ##__VA_ARGS__) -#else -#define DBGCONN(c, fmt, ...) -#endif /* Max # of events from epoll processed at once */ #define MAX_EVENTS 10 @@ -164,7 +140,8 @@ close_conn(uzfs_mgmt_conn_t *conn) { async_task_t *async_task; - DBGCONN(conn, "Closing the connection"); + if (conn->conn_state != CS_CONNECT) + DBGCONN(conn, "Closing the connection"); /* Release resources tight to the conn */ if (conn->conn_buf != NULL) { @@ -241,7 +218,8 @@ connect_to_tgt(uzfs_mgmt_conn_t *conn) /* EINPROGRESS means that EPOLLOUT will tell us when connect is done */ if (rc != 0 && errno != EINPROGRESS) { close(sfd); - DBGCONN(conn, "Failed to connect"); + LOG_ERRNO("Failed to connect to %s:%d", conn->conn_host, + conn->conn_port); return (-1); } return (sfd); @@ -515,11 +493,11 @@ uzfs_zvol_mgmt_do_handshake(uzfs_mgmt_conn_t *conn, zvol_io_hdr_t *hdrp, mgmt_ack_t mgmt_ack; zvol_io_hdr_t hdr; - printf("Volume %s sent for enq\n", name); + LOG_INFO("Handshake on zvol %s", name); bzero(&mgmt_ack, sizeof (mgmt_ack)); if (uzfs_zvol_get_ip(mgmt_ack.ip) == -1) { - fprintf(stderr, "Unable to get IP with err: %d\n", errno); + LOG_ERRNO("Unable to get IP"); return (reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq)); } @@ -535,8 +513,7 @@ uzfs_zvol_mgmt_do_handshake(uzfs_mgmt_conn_t *conn, zvol_io_hdr_t *hdrp, */ if (zv->zv_objset == NULL) { if (uzfs_hold_dataset(zv) != 0) { - fprintf(stderr, "Failed to hold zvol during " - "handshake\n"); + LOG_ERR("Failed to hold zvol during handshake"); return (reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq)); } @@ -638,7 +615,8 @@ uzfs_zvol_execute_async_command(void *arg) case ZVOL_OPCODE_SNAP_CREATE: rc = dmu_objset_snapshot_one(zinfo->name, snapname); if (rc != 0) { - fprintf(stderr, "Snapshot create failed: %d\n", rc); + LOG_ERR("Failed to create %s@%s: %d", + zinfo->name, snapname, rc); async_task->status = ZVOL_OP_STATUS_FAILED; } else { async_task->status = ZVOL_OP_STATUS_OK; @@ -649,7 +627,8 @@ uzfs_zvol_execute_async_command(void *arg) rc = dsl_destroy_snapshot(dataset, B_FALSE); strfree(dataset); if (rc != 0) { - fprintf(stderr, "Snapshot destroy failed: %d\n", rc); + LOG_ERR("Failed to destroy %s@%s: %d", + zinfo->name, snapname, rc); async_task->status = ZVOL_OP_STATUS_FAILED; } else { async_task->status = ZVOL_OP_STATUS_OK; @@ -717,14 +696,14 @@ uzfs_zvol_rebuild_dw_replica_start(uzfs_mgmt_conn_t *conn, zvol_io_hdr_t *hdrp, for (; rebuild_op_cnt > 0; rebuild_op_cnt--, mack++) { if (mack->volname[0] != '\0') { - printf("Replica %s at %s:%u helping in rebuild\n", + LOG_INFO("zvol %s at %s:%u helping in rebuild", mack->volname, mack->ip, mack->port); } if (zinfo == NULL) { zinfo = uzfs_zinfo_lookup(mack->dw_volname); if ((zinfo == NULL) || (zinfo->mgmt_conn != conn)) { - printf("Replica %s not found or not matching " - "conn\n", mack->dw_volname); + LOG_ERR("zvol %s not found or not matching " + "connection", mack->dw_volname); return (reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq)); @@ -744,7 +723,7 @@ uzfs_zvol_rebuild_dw_replica_start(uzfs_mgmt_conn_t *conn, zvol_io_hdr_t *hdrp, uzfs_zvol_set_status(zinfo->zv, ZVOL_STATUS_HEALTHY); uzfs_update_ionum_interval(zinfo, 0); - printf("Rebuild of replica %s completed\n", + LOG_INFO("Rebuild of zvol %s completed", zinfo->name); uzfs_zinfo_drop_refcnt(zinfo, B_FALSE); break; @@ -754,8 +733,8 @@ uzfs_zvol_rebuild_dw_replica_start(uzfs_mgmt_conn_t *conn, zvol_io_hdr_t *hdrp, } else { if (strncmp(zinfo->name, mack->dw_volname, MAXNAMELEN) != 0) { - printf("Replica %s not matching with zinfo" - " %s\n", mack->dw_volname, zinfo->name); + LOG_ERR("zvol %s not matching with zinfo %s", + mack->dw_volname, zinfo->name); return (reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq)); @@ -766,8 +745,8 @@ uzfs_zvol_rebuild_dw_replica_start(uzfs_mgmt_conn_t *conn, zvol_io_hdr_t *hdrp, io_sfd = create_and_bind("", B_FALSE, B_FALSE); if (io_sfd < 0) { /* Fail this rebuild process entirely */ - fprintf(stderr, "Rebuild IO socket create and bind" - " failed on volume: %s\n", zinfo->name); + LOG_ERR("Rebuild IO socket create and bind" + " failed on zvol: %s", zinfo->name); uzfs_zvol_set_rebuild_status(zinfo->zv, ZVOL_REBUILDING_FAILED); uzfs_zinfo_drop_refcnt(zinfo, B_FALSE); @@ -823,7 +802,7 @@ process_message(uzfs_mgmt_conn_t *conn) if (((zinfo = uzfs_zinfo_lookup(zvol_name)) == NULL) || (zinfo->mgmt_conn != conn)) { - fprintf(stderr, "Unknown zvol: %s\n", zvol_name); + LOG_ERR("Unknown zvol: %s", zvol_name); rc = reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq); break; @@ -861,7 +840,7 @@ process_message(uzfs_mgmt_conn_t *conn) zvol_name[payload_size] = '\0'; snap = strchr(zvol_name, '@'); if (snap == NULL) { - fprintf(stderr, "Invalid snapshot name: %s\n", + LOG_ERR("Invalid snapshot name: %s", zvol_name); rc = reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq); @@ -871,7 +850,7 @@ process_message(uzfs_mgmt_conn_t *conn) /* ref will be released when async command has finished */ if (((zinfo = uzfs_zinfo_lookup(zvol_name)) == NULL) || (zinfo->mgmt_conn != conn)) { - fprintf(stderr, "Unknown zvol: %s\n", zvol_name); + LOG_ERR("Unknown zvol: %s", zvol_name); rc = reply_nodata(conn, ZVOL_OP_STATUS_FAILED, hdrp->opcode, hdrp->io_seq); break; @@ -946,7 +925,7 @@ move_to_next_state(uzfs_mgmt_conn_t *conn) kmem_free(conn->conn_buf, sizeof (uint16_t)); conn->conn_buf = NULL; if (vers != REPLICA_VERSION) { - fprintf(stderr, "invalid replica protocol version %d\n", + LOG_ERR("Invalid replica protocol version %d", vers); rc = reply_nodata(conn, ZVOL_OP_STATUS_VERSION_MISMATCH, 0, 0); @@ -1068,10 +1047,10 @@ uzfs_zvol_mgmt_thread(void *arg) if (events[i].events & EPOLLERR) { if (conn->conn_state == CS_CONNECT) { - DBGCONN(conn, "Failed to connect"); + LOG_ERR("Failed to connect to %s:%d", + conn->conn_host, conn->conn_port); } else { - fprintf(stderr, "Error on connection " - "to %s:%d\n", + LOG_ERR("Error on connection to %s:%d", conn->conn_host, conn->conn_port); } if (close_conn(conn) != 0) @@ -1157,6 +1136,6 @@ uzfs_zvol_mgmt_thread(void *arg) mutex_exit(&async_tasks_mtx); mutex_destroy(&async_tasks_mtx); - fprintf(stderr, "uzfs_zvol_mgmt_thread thread exiting\n"); + LOG_DEBUG("uzfs_zvol_mgmt thread exiting"); zk_thread_exit(); } diff --git a/cmd/zrepl/zrepl.c b/cmd/zrepl/zrepl.c index f36b2b552380..44ff351d344a 100644 --- a/cmd/zrepl/zrepl.c +++ b/cmd/zrepl/zrepl.c @@ -45,22 +45,19 @@ uzfs_zvol_read_header(int fd, zvol_io_hdr_t *hdr) rc = uzfs_zvol_socket_read(fd, (char *)hdr, sizeof (hdr->version)); - if (rc != 0) { - ZREPL_ERRLOG("error reading from socket: %d\n", errno); + if (rc != 0) return (-1); - } + if (hdr->version != REPLICA_VERSION) { - ZREPL_ERRLOG("invalid replica protocol version %d\n", + LOG_ERR("invalid replica protocol version %d", hdr->version); return (1); } rc = uzfs_zvol_socket_read(fd, ((char *)hdr) + sizeof (hdr->version), sizeof (*hdr) - sizeof (hdr->version)); - if (rc != 0) { - ZREPL_ERRLOG("error reading from socket: %d\n", errno); + if (rc != 0) return (-1); - } return (0); } @@ -89,27 +86,27 @@ open_zvol(int fd, zvol_info_t **zinfopp) * reading header */ if (uzfs_zvol_read_header(fd, &hdr) != 0) { - ZREPL_ERRLOG("error reading open header\n"); + LOG_ERR("error reading open header"); return (-1); } if (hdr.opcode != ZVOL_OPCODE_OPEN) { - ZREPL_ERRLOG("Zvol must be opened first\n"); + LOG_ERR("zvol must be opened first"); return (-1); } if (hdr.len != sizeof (open_data)) { - ZREPL_ERRLOG("Invalid payload length for open\n"); + LOG_ERR("Invalid payload length for open"); return (-1); } rc = uzfs_zvol_socket_read(fd, (char *)&open_data, sizeof (open_data)); if (rc != 0) { - ZREPL_ERRLOG("Payload read failed: %d\n", errno); + LOG_ERR("Payload read failed"); return (-1); } open_data.volname[MAX_NAME_LEN - 1] = '\0'; zinfo = uzfs_zinfo_lookup(open_data.volname); if (zinfo == NULL) { - ZREPL_ERRLOG("zvol %s not found", open_data.volname); + LOG_ERR("zvol %s not found", open_data.volname); hdr.status = ZVOL_OP_STATUS_FAILED; goto open_reply; } @@ -117,14 +114,14 @@ open_zvol(int fd, zvol_info_t **zinfopp) ASSERT3P(zv, !=, NULL); if (zv->zv_metavolblocksize != 0 && zv->zv_metavolblocksize != open_data.tgt_block_size) { - ZREPL_ERRLOG("Conflicting block size"); + LOG_ERR("Conflicting block size"); hdr.status = ZVOL_OP_STATUS_FAILED; goto open_reply; } // validate block size (only one bit is set in the number) if (open_data.tgt_block_size == 0 || (open_data.tgt_block_size & (open_data.tgt_block_size - 1)) != 0) { - ZREPL_ERRLOG("Invalid block size"); + LOG_ERR("Invalid block size"); hdr.status = ZVOL_OP_STATUS_FAILED; goto open_reply; } @@ -137,14 +134,14 @@ open_zvol(int fd, zvol_info_t **zinfopp) */ if (zv->zv_objset == NULL && uzfs_hold_dataset(zv) != 0) { (void) pthread_mutex_unlock(&zinfo->zinfo_mutex); - ZREPL_ERRLOG("Failed to hold zvol during open\n"); + LOG_ERR("Failed to hold zvol during open"); hdr.status = ZVOL_OP_STATUS_FAILED; goto open_reply; } if (uzfs_update_metadata_granularity(zv, open_data.tgt_block_size) != 0) { (void) pthread_mutex_unlock(&zinfo->zinfo_mutex); - ZREPL_ERRLOG("Failed to set granularity of metadata\n"); + LOG_ERR("Failed to set granularity of metadata"); hdr.status = ZVOL_OP_STATUS_FAILED; goto open_reply; } @@ -180,7 +177,7 @@ open_zvol(int fd, zvol_info_t **zinfopp) hdr.len = 0; rc = uzfs_zvol_socket_write(fd, (char *)&hdr, sizeof (hdr)); if (rc == -1) - ZREPL_ERRLOG("failed to send reply for open request\n"); + LOG_ERR("Failed to send reply for open request"); if (hdr.status != ZVOL_OP_STATUS_OK) { if (zinfo != NULL) uzfs_zinfo_drop_refcnt(zinfo, B_FALSE); @@ -213,14 +210,13 @@ uzfs_zvol_io_receiver(void *arg) while (1) { rc = uzfs_zvol_socket_read(fd, (char *)&hdr, sizeof (hdr)); - if (rc != 0) { - ZREPL_ERRLOG("error reading from socket: %d\n", errno); + if (rc != 0) goto exit; - } + if (hdr.opcode != ZVOL_OPCODE_WRITE && hdr.opcode != ZVOL_OPCODE_READ && hdr.opcode != ZVOL_OPCODE_SYNC) { - ZREPL_ERRLOG("Unexpected opcode %d\n", hdr.opcode); + LOG_ERR("Unexpected opcode %d", hdr.opcode); goto exit; } @@ -230,12 +226,10 @@ 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); - ZREPL_ERRLOG("Socket read failed with " - "error: %d\n", errno); goto exit; } } else if (hdr.opcode != ZVOL_OPCODE_READ && hdr.len > 0) { - ZREPL_ERRLOG("Unexpected payload for opcode %d\n", + LOG_ERR("Unexpected payload for opcode %d", hdr.opcode); zio_cmd_free(&zio_cmd); goto exit; @@ -249,7 +243,7 @@ uzfs_zvol_io_receiver(void *arg) } exit: if (zinfo != NULL) { - ZREPL_LOG("uzfs_zvol_io_receiver thread exiting, volume: %s\n", + 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; @@ -272,7 +266,7 @@ uzfs_zvol_io_receiver(void *arg) (void) pthread_mutex_unlock(&zinfo->zinfo_mutex); uzfs_zinfo_drop_refcnt(zinfo, B_FALSE); } else { - ZREPL_LOG("uzfs_zvol_io_receiver thread exiting\n"); + LOG_DEBUG("uzfs_zvol_io_receiver thread exiting"); } zk_thread_exit(); } @@ -296,7 +290,7 @@ uzfs_zvol_rebuild_scanner_callback(off_t offset, size_t len, hdr.len = len; hdr.flags = ZVOL_OP_FLAG_REBUILD; hdr.status = ZVOL_OP_STATUS_OK; - printf("IO number for rebuild %ld\n", metadata->io_num); + LOG_INFO("IO number for rebuild %ld", metadata->io_num); zio_cmd = zio_cmd_alloc(&hdr, warg->fd); /* Take refcount for uzfs_zvol_worker to work on it */ uzfs_zinfo_take_refcnt(zinfo, B_FALSE); @@ -330,7 +324,7 @@ uzfs_zvol_rebuild_scanner(void *arg) goto exit; } - printf("op_code=%d io_seq=%ld\n", hdr.opcode, hdr.io_seq); + LOG_DEBUG("op_code=%d io_seq=%ld", hdr.opcode, hdr.io_seq); /* Handshake yet to happen */ if ((hdr.opcode != ZVOL_OPCODE_HANDSHAKE) && (zinfo == NULL)) { @@ -343,28 +337,26 @@ uzfs_zvol_rebuild_scanner(void *arg) rc = uzfs_zvol_socket_read(fd, name, hdr.len); if (rc != 0) { kmem_free(name, hdr.len); - ZREPL_ERRLOG("Socket read error: %d\n", errno); goto exit; } /* Handshake already happened */ if (zinfo != NULL) { - ZREPL_ERRLOG("Again handshake request on " - " for volume:%s \n", - fd, zinfo->name, name); + LOG_ERR("Second handshake on %s connection for " + "zvol %s", + zinfo->name, name); kmem_free(name, hdr.len); goto exit; } zinfo = uzfs_zinfo_lookup(name); if (zinfo == NULL) { - ZREPL_ERRLOG("Volume/LUN: %s not found", name); + LOG_ERR("zvol %s not found", name); kmem_free(name, hdr.len); goto exit; } - ZREPL_ERRLOG("Rebuild scanner started on volume:%s\n", - name); + LOG_INFO("Rebuild scanner started on zvol %s", name); kmem_free(name, hdr.len); warg.zinfo = zinfo; warg.fd = fd; @@ -377,8 +369,8 @@ uzfs_zvol_rebuild_scanner(void *arg) rebuild_req_offset = hdr.offset; rebuild_req_len = hdr.len; - ZREPL_LOG("Checkpointed IO_seq: %ld, " - "Rebuild Req offset:%ld, Rebuild Req length:%ld\n", + LOG_INFO("Checkpointed IO_seq: %ld, " + "Rebuild Req offset: %ld, Rebuild Req length: %ld", metadata.io_num, rebuild_req_offset, rebuild_req_len); @@ -386,8 +378,8 @@ uzfs_zvol_rebuild_scanner(void *arg) uzfs_zvol_rebuild_scanner_callback, rebuild_req_offset, rebuild_req_len, &warg); if (rc != 0) { - ZREPL_ERRLOG("Rebuild scanning failed on " - "Volume:%s\n", zinfo->name); + LOG_ERR("Rebuild scanning failed on zvol %s", + zinfo->name); } bzero(&hdr, sizeof (hdr)); hdr.status = ZVOL_OP_STATUS_OK; @@ -402,24 +394,24 @@ uzfs_zvol_rebuild_scanner(void *arg) break; case ZVOL_OPCODE_REBUILD_COMPLETE: - ZREPL_LOG("Rebuild process is over on Replica:%s\n", + LOG_INFO("Rebuild process is over on zvol %s", zinfo->name); goto exit; break; default: - ZREPL_LOG("Wrong opcode:%d\n", hdr.opcode); + LOG_ERR("Wrong opcode: %d", hdr.opcode); goto exit; break; } exit: if (zinfo != NULL) { - ZREPL_LOG("uzfs_zvol_rebuild_scanner thread exiting," - " volume:%s\n", zinfo->name); + LOG_DEBUG("uzfs_zvol_rebuild_scanner thread for zvol %s " + "exiting", zinfo->name); uzfs_zinfo_drop_refcnt(zinfo, B_FALSE); } else { - printf("uzfs_zvol_rebuild_scanner thread exiting\n"); + LOG_DEBUG("uzfs_zvol_rebuild_scanner thread exiting"); } if (fd != -1) @@ -460,8 +452,7 @@ uzfs_zvol_io_conn_acceptor(void) rc = listen(io_sfd, SOMAXCONN); if (rc == -1) { - ZREPL_ERRLOG("listen() on IO_SFD failed with errno:%d\n", - errno); + LOG_ERRNO("listen on IO FD in acceptor failed"); goto exit; } @@ -472,14 +463,13 @@ uzfs_zvol_io_conn_acceptor(void) rc = listen(rebuild_fd, SOMAXCONN); if (rc == -1) { - ZREPL_ERRLOG("listen() on REBUILD_FD failed with errno:%d\n", - errno); + LOG_ERRNO("listen on rebuild FD in acceptor failed"); goto exit; } efd = epoll_create1(0); if (efd == -1) { - ZREPL_ERRLOG("epoll_create() failed with errno:%d\n", errno); + LOG_ERRNO("epoll_create1 failed"); goto exit; } @@ -487,8 +477,7 @@ uzfs_zvol_io_conn_acceptor(void) event.events = flags; rc = epoll_ctl(efd, EPOLL_CTL_ADD, io_sfd, &event); if (rc == -1) { - ZREPL_ERRLOG("epoll_ctl() for IO_SFD failed with errno:%d\n", - errno); + LOG_ERRNO("epoll_ctl on IO FD failed"); goto exit; } @@ -496,8 +485,7 @@ uzfs_zvol_io_conn_acceptor(void) event.events = flags; rc = epoll_ctl(efd, EPOLL_CTL_ADD, rebuild_fd, &event); if (rc == -1) { - ZREPL_ERRLOG("epoll_ctl() for REBUILD_FD failed with " - "errno:%d\n", errno); + LOG_ERRNO("epoll_ctl on rebuild FD failed"); goto exit; } @@ -527,7 +515,7 @@ uzfs_zvol_io_conn_acceptor(void) * (why were we notified then?) */ if (!(events[i].events & EPOLLIN)) { - ZREPL_ERRLOG("epoll err() :%d\n", errno); + LOG_ERRNO("epoll failed"); if (events[i].data.fd == io_sfd) { io_sfd = -1; } else { @@ -548,7 +536,7 @@ uzfs_zvol_io_conn_acceptor(void) in_len = sizeof (in_addr); new_fd = accept(events[i].data.fd, &in_addr, &in_len); if (new_fd == -1) { - ZREPL_ERRLOG("accept err() :%d\n", errno); + LOG_ERRNO("accept failed"); goto exit; } #ifdef DEBUG @@ -558,8 +546,8 @@ uzfs_zvol_io_conn_acceptor(void) sbuf, sizeof (sbuf), NI_NUMERICHOST | NI_NUMERICSERV); if (rc == 0) { - ZREPL_LOG("Accepted connection on fd %ld " - "(host=%s, port=%s)\n", new_fd, hbuf, sbuf); + LOG_DEBUG("Accepted connection from %s:%s", + hbuf, sbuf); } kmem_free(hbuf, sizeof (NI_MAXHOST)); @@ -571,7 +559,7 @@ uzfs_zvol_io_conn_acceptor(void) (void *)new_fd, 0, NULL, TS_RUN, 0, PTHREAD_CREATE_DETACHED); } else { - ZREPL_ERRLOG("Connection req for rebuild\n"); + LOG_INFO("Connection req for rebuild"); thrd_info = zk_thread_create(NULL, 0, uzfs_zvol_rebuild_scanner, (void *)new_fd, 0, NULL, TS_RUN, 0, @@ -593,7 +581,7 @@ uzfs_zvol_io_conn_acceptor(void) if (efd != -1) close(efd); - ZREPL_ERRLOG("uzfs_zvol_io_conn_acceptor thread exiting\n"); + LOG_DEBUG("uzfs_zvol_io_conn_acceptor thread exiting"); zk_thread_exit(); } @@ -695,7 +683,7 @@ uzfs_zvol_io_ack_sender(void *arg) STAILQ_REMOVE_HEAD(&zinfo->complete_queue, cmd_link); (void) pthread_mutex_unlock(&zinfo->zinfo_mutex); - ZREPL_LOG("ACK for op:%d with seq-id %ld\n", + LOG_DEBUG("ACK for op: %d, seq-id: %ld", zio_cmd->hdr.opcode, zio_cmd->hdr.io_seq); /* account for space taken by metadata headers */ @@ -717,7 +705,7 @@ uzfs_zvol_io_ack_sender(void *arg) rc = uzfs_zvol_socket_write(zio_cmd->conn, (char *)&zio_cmd->hdr, sizeof (zio_cmd->hdr)); if (rc == -1) { - ZREPL_ERRLOG("socket write err :%d\n", errno); + LOG_ERRNO("socket write err"); if (zio_cmd->conn == fd) { zio_cmd_free(&zio_cmd); (void) pthread_mutex_lock(&zinfo->zinfo_mutex); @@ -732,8 +720,7 @@ uzfs_zvol_io_ack_sender(void *arg) /* Send data read from disk */ rc = uzfs_send_reads(zio_cmd->conn, zio_cmd); if (rc == -1) { - ZREPL_ERRLOG("socket write err :%d\n", - errno); + LOG_ERRNO("socket write err"); if (zio_cmd->conn == fd) { (void) pthread_mutex_lock( &zinfo->zinfo_mutex); @@ -748,7 +735,7 @@ uzfs_zvol_io_ack_sender(void *arg) zio_cmd_free(&zio_cmd); } exit: - ZREPL_LOG("uzfs_zvol_io_ack_sender thread exiting, volume:%s\n", + LOG_DEBUG("uzfs_zvol_io_ack_sender thread for zvol %s exiting", zinfo->name); close(fd); @@ -764,18 +751,6 @@ uzfs_zvol_io_ack_sender(void *arg) zk_thread_exit(); } -static void -uzfs_zrepl_open_log(void) -{ - openlog("zrepl", LOG_PID, LOG_LOCAL7); -} - -static void -uzfs_zrepl_close_log(void) -{ - closelog(); -} - void zrepl_svc_run(void) { @@ -801,30 +776,44 @@ zrepl_svc_run(void) int main(int argc, char **argv) { - int rc; + /* Use opt parsing lib if we have more options */ + zrepl_log_level = LOG_LEVEL_INFO; + if (argc == 3 && strcmp(argv[1], "-l") == 0) { + if (strcmp(argv[2], "debug") == 0) + zrepl_log_level = LOG_LEVEL_DEBUG; + else if (strcmp(argv[2], "info") == 0) + zrepl_log_level = LOG_LEVEL_INFO; + else if (strcmp(argv[2], "error") == 0) + zrepl_log_level = LOG_LEVEL_ERR; + else { + fprintf(stderr, "Log level should be one of " + "\"debug\", \"info\" or \"error\"\n"); + return (-1); + } + } + if (getenv("CONFIG_LOAD_DISABLE") != NULL) { - printf("disabled auto import (reading of zpool.cache)\n"); + LOG_INFO("disabled auto import (reading of zpool.cache)"); zfs_autoimport_disable = 1; } else { - printf("auto importing pools by reading zpool.cache files\n"); + LOG_INFO("auto importing pools by reading zpool.cache files"); zfs_autoimport_disable = 0; } zinfo_create_hook = &zinfo_create_cb; zinfo_destroy_hook = &zinfo_destroy_cb; rc = uzfs_init(); - uzfs_zrepl_open_log(); if (rc != 0) { - ZREPL_ERRLOG("initialization errored.. %d\n", rc); + LOG_ERR("initialization errored: %d", rc); return (-1); } /* Ignore SIGPIPE signal */ signal(SIGPIPE, SIG_IGN); if (libuzfs_ioctl_init() < 0) { - ZREPL_ERRLOG("Failed to initialize libuzfs ioctl\n"); + LOG_ERR("Failed to initialize libuzfs ioctl"); goto initialize_error; } @@ -834,7 +823,6 @@ main(int argc, char **argv) } initialize_error: - uzfs_zrepl_close_log(); uzfs_fini(); return (-1); } diff --git a/include/zrepl_mgmt.h b/include/zrepl_mgmt.h index 9fe033341b9e..5a6761994e63 100644 --- a/include/zrepl_mgmt.h +++ b/include/zrepl_mgmt.h @@ -25,8 +25,8 @@ #ifndef ZREPL_MGMT_H #define ZREPL_MGMT_H +#include #include -#include #include #include #include "zrepl_prot.h" @@ -43,6 +43,26 @@ extern "C" { #define REBUILD_IO_SERVER_PORT "3233" #define IO_SERVER_PORT "3232" +enum zrepl_log_level { + LOG_LEVEL_DEBUG, + LOG_LEVEL_INFO, + LOG_LEVEL_ERR, +}; + +extern enum zrepl_log_level zrepl_log_level; +void zrepl_log(enum zrepl_log_level lvl, const char *fmt, ...); + +/* shortcuts to invoke log function with given log level */ +#define LOG_DEBUG(fmt, ...) \ + do { \ + if (unlikely(zrepl_log_level <= LOG_LEVEL_DEBUG)) \ + zrepl_log(LOG_LEVEL_DEBUG, fmt, ##__VA_ARGS__); \ + } while (0) +#define LOG_INFO(fmt, ...) zrepl_log(LOG_LEVEL_INFO, fmt, ##__VA_ARGS__) +#define LOG_ERR(fmt, ...) zrepl_log(LOG_LEVEL_ERR, fmt, ##__VA_ARGS__) +#define LOG_ERRNO(fmt, ...) zrepl_log(LOG_LEVEL_ERR, \ + fmt ": %s", ##__VA_ARGS__, strerror(errno)) + SLIST_HEAD(zvol_list, zvol_info_s); extern kmutex_t zvol_list_mutex; extern struct zvol_list zvol_list; @@ -137,24 +157,6 @@ void uzfs_zvol_store_last_committed_io_no(zvol_state_t *zv, extern int create_and_bind(const char *port, int bind_needed, boolean_t nonblocking); -#define ZREPL_LOG(fmt, ...) syslog(LOG_NOTICE, \ - "%-18.18s:%4d: " fmt, __func__, __LINE__, ##__VA_ARGS__) - -#define ZREPL_NOTICELOG(fmt, ...) syslog(LOG_NOTICE, \ - "%-18.18s:%4d: " fmt, __func__, __LINE__, ##__VA_ARGS__) - -#define ZREPL_ERRLOG(fmt, ...) syslog(LOG_ERR, \ - "%-18.18s:%4d: " fmt, __func__, __LINE__, ##__VA_ARGS__) - -#define ZREPL_WARNLOG(fmt, ...) syslog(LOG_ERR, \ - "%-18.18s:%4d: " fmt, __func__, __LINE__, ##__VA_ARGS__) - -#define ZREPL_TRACELOG(FLAG, fmt, ...) \ - do { \ - syslog(LOG_NOTICE, "%-18.18s:%4d: " \ - fmt, __func__, __LINE__, ##__VA_ARGS__); \ - } while (0) - #ifdef __cplusplus } #endif diff --git a/lib/libzpool/uzfs_mgmt.c b/lib/libzpool/uzfs_mgmt.c index 758c04e29987..9348f1c653b6 100644 --- a/lib/libzpool/uzfs_mgmt.c +++ b/lib/libzpool/uzfs_mgmt.c @@ -467,13 +467,12 @@ uzfs_zvol_create_cb(const char *ds_name, void *arg) char *ip; if (strrchr(ds_name, '@') != NULL) { - printf("no owning dataset for snapshots: %s\n", ds_name); return (0); } error = uzfs_own_dataset(ds_name, &zv); if (error) { - printf("Failed to open dataset: %s\n", ds_name); + /* happens normally for all non-zvol-type datasets */ return (error); } @@ -484,20 +483,19 @@ uzfs_zvol_create_cb(const char *ds_name, void *arg) strncpy(zv->zv_target_host, ip, sizeof (zv->zv_target_host)); else { - printf("target IP address is not set for %s\n", - ds_name); + LOG_ERR("target IP address is not set for %s", ds_name); uzfs_close_dataset(zv); return (error); } } else { if (zv->zv_target_host[0] == '\0') { - printf("target IP address is NULL for %s\n", ds_name); + LOG_ERR("target IP address is empty for %s", ds_name); uzfs_close_dataset(zv); return (EINVAL); } } if (uzfs_zinfo_init(zv, ds_name, nvprops) != 0) { - printf("Failed in uzfs_zinfo_init\n"); + LOG_ERR("Failed in uzfs_zinfo_init"); return (error); } @@ -527,12 +525,7 @@ uzfs_zvol_create_minors(spa_t *spa, const char *name) int uzfs_zvol_destroy_cb(const char *ds_name, void *arg) { - if (ds_name) - printf("deleting ds_name %s\n", ds_name); - else - printf("deleting all dsnames on pool!\n "); - uzfs_zinfo_destroy(ds_name, arg); - return (0); + return (uzfs_zinfo_destroy(ds_name, arg)); } /* disowns, closes dataset */ diff --git a/lib/libzpool/uzfs_rebuilding.c b/lib/libzpool/uzfs_rebuilding.c index d77a307031a4..b42465f79312 100644 --- a/lib/libzpool/uzfs_rebuilding.c +++ b/lib/libzpool/uzfs_rebuilding.c @@ -29,6 +29,7 @@ #include #include #include +#include #define ADD_TO_IO_CHUNK_LIST(list, e_offset, e_len, count) \ do { \ @@ -82,9 +83,8 @@ get_snapshot_zv(zvol_state_t *zv, char *snap_name, zvol_state_t **snap_zv) if (ret == ENOENT) { ret = dmu_objset_snapshot_one(zv->zv_name, snap_name); if (ret) { - printf("Failed to create snapshot for %s err(%d)\n", - zv->zv_name, ret); - printf("vol:%s snap:%s\n", dataset, snap_name); + LOG_ERR("Failed to create snapshot %s@%s: %d", + zv->zv_name, snap_name, ret); strfree(dataset); return (ret); } @@ -98,7 +98,7 @@ get_snapshot_zv(zvol_state_t *zv, char *snap_name, zvol_state_t **snap_zv) if (ret != 0) { strfree(dataset); - printf("Failed to own snapshot.. err(%d)\n", ret); + LOG_ERR("Failed to own snapshot: %d", ret); return (ret); } @@ -149,8 +149,8 @@ uzfs_get_io_diff(zvol_state_t *zv, blk_metadata_t *low, ret = get_snapshot_zv(zv, snap_name, &snap_zv); if (ret != 0) { - printf("failed to get snapshot info for %s io_num:%lu\n", - zv->zv_name, low->io_num); + LOG_ERR("Failed to get info about %s@%s io_num %lu", + zv->zv_name, snap_name, low->io_num); strfree(snap_name); return (ret); } @@ -263,7 +263,7 @@ uzfs_get_nonoverlapping_ondisk_blks(zvol_state_t *zv, uint64_t offset, ret = uzfs_read_metadata(zv, ondisk_metadata_buf, ondisk_metablk.m_offset, ondisk_metablk.m_len, &rd_rlen); if (ret || rd_rlen != ondisk_metablk.m_len) { - printf("failed to read metadata\n"); + LOG_ERR("Failed to read metadata"); goto exit; } diff --git a/lib/libzpool/zrepl_mgmt.c b/lib/libzpool/zrepl_mgmt.c index 42e0bb148ee6..05aa02baf6c0 100644 --- a/lib/libzpool/zrepl_mgmt.c +++ b/lib/libzpool/zrepl_mgmt.c @@ -1,6 +1,5 @@ #include #include -#include #include #include #include @@ -27,6 +26,54 @@ struct zvol_list stale_zv_list; static int uzfs_zinfo_free(zvol_info_t *zinfo); +enum zrepl_log_level zrepl_log_level; + +/* + * Log message to stdout/stderr if log level allows it. + */ +void +zrepl_log(enum zrepl_log_level lvl, const char *fmt, ...) +{ + va_list args; + struct timeval tv; + struct tm *timeinfo; + unsigned int ms; + char line[512]; + FILE *outf; + + if (lvl < zrepl_log_level) + return; + + /* Create timestamp prefix */ + gettimeofday(&tv, NULL); + timeinfo = localtime(&tv.tv_sec); + ms = tv.tv_usec / 1000; + strftime(line, sizeof (line), "%H:%M:%S.", timeinfo); + snprintf(line + 9, sizeof (line) - 9, "%03u", ms); + + switch (lvl) { + case LOG_LEVEL_DEBUG: + outf = stdout; + strncpy(line + 12, " DEBUG ", sizeof (line) - 12); + break; + case LOG_LEVEL_INFO: + outf = stdout; + strncpy(line + 12, " INFO ", sizeof (line) - 12); + break; + case LOG_LEVEL_ERR: + outf = stderr; + strncpy(line + 12, " ERROR ", sizeof (line) - 12); + break; + default: + ASSERT(0); + } + + va_start(args, fmt); + vsnprintf(line + 19, sizeof (line) - 19, fmt, args); + va_end(args); + fprintf(outf, "%s\n", line); +} + int create_and_bind(const char *port, int bind_needed, boolean_t nonblock) { @@ -59,8 +106,6 @@ create_and_bind(const char *port, int bind_needed, boolean_t nonblock) } s = bind(sfd, rp->ai_addr, rp->ai_addrlen); if (s == 0) { - /* We managed to bind successfully! */ - printf("bind is successful\n"); break; } @@ -68,7 +113,6 @@ create_and_bind(const char *port, int bind_needed, boolean_t nonblock) } if (rp == NULL) { - printf("bind failed with err\n"); return (-1); } @@ -115,7 +159,7 @@ uzfs_zinfo_take_refcnt(zvol_info_t *zinfo, int locked) static void uzfs_insert_zinfo_list(zvol_info_t *zinfo) { - + LOG_INFO("Instantiating zvol %s", zinfo->name); /* Base refcount is taken here */ (void) mutex_enter(&zvol_list_mutex); uzfs_zinfo_take_refcnt(zinfo, B_TRUE); @@ -126,7 +170,7 @@ uzfs_insert_zinfo_list(zvol_info_t *zinfo) static void uzfs_remove_zinfo_list(zvol_info_t *zinfo) { - + LOG_INFO("Removing zvol %s", zinfo->name); SLIST_REMOVE(&zvol_list, zinfo, zvol_info_s, zinfo_next); (void) pthread_mutex_lock(&zinfo->zinfo_mutex); zinfo->state = ZVOL_INFO_STATE_OFFLINE; @@ -196,7 +240,6 @@ uzfs_zinfo_destroy_mutex(zvol_info_t *zinfo) int uzfs_zinfo_destroy(const char *name, spa_t *spa) { - zvol_info_t *zinfo = NULL; zvol_info_t *zt = NULL; int namelen = ((name) ? strlen(name) : 0); @@ -215,13 +258,11 @@ uzfs_zinfo_destroy(const char *name, spa_t *spa) } } } else { - SLIST_FOREACH_SAFE(zinfo, &zvol_list, zinfo_next, zt) { if (name == NULL || (strcmp(zinfo->name, name) == 0) || ((strncmp(zinfo->name, name, namelen) == 0) && zinfo->name[namelen] == '/' && zinfo->name[namelen + 1] == '\0')) { - printf("destroying %s\n", zinfo->name); zv = zinfo->zv; uzfs_remove_zinfo_list(zinfo); uzfs_close_dataset(zv); @@ -229,10 +270,7 @@ uzfs_zinfo_destroy(const char *name, spa_t *spa) } } } - - (void) mutex_exit(&zvol_list_mutex); - - printf("uzfs_zinfo_destroy path\n"); + mutex_exit(&zvol_list_mutex); return (0); } @@ -263,7 +301,6 @@ uzfs_zinfo_init(void *zv, const char *ds_name, nvlist_t *create_props) if (zinfo_create_hook) (*zinfo_create_hook)(zinfo, create_props); - printf("uzfs_zinfo_init in success path\n"); return (0); } @@ -276,7 +313,6 @@ uzfs_zinfo_free(zvol_info_t *zinfo) taskq_destroy(zinfo->uzfs_zvol_taskq); (void) uzfs_zinfo_destroy_mutex(zinfo); ASSERT(STAILQ_EMPTY(&zinfo->complete_queue)); - printf("Freeing volume =%s\n", zinfo->name); free(zinfo); return (0);