From c95917ecfefbee86f04ea79681fe40c75c017a0e Mon Sep 17 00:00:00 2001 From: Andrea Mazzoleni Date: Mon, 21 Oct 2013 21:56:53 +0200 Subject: [PATCH] Adds more logging in scrub and sync. --- check.c | 20 ++++++++++---------- dry.c | 2 +- scrub.c | 10 +++++----- sync.c | 35 +++++++++++++++++++++++++++-------- 4 files changed, 43 insertions(+), 24 deletions(-) diff --git a/check.c b/check.c index a9429f59..c8c8f465 100644 --- a/check.c +++ b/check.c @@ -233,7 +233,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_hash_matching(state, rehash, diskmax, failed, failed_map, failed_count, buffer, buffer_zero)) return 0; - fprintf(stdlog, "error:%u:%s: Data error\n", pos, lev_config_name(COMBO1[i].a)); + fprintf(stdlog, "parity_error:%u:%s: Data error\n", pos, lev_config_name(COMBO1[i].a)); ++error; } } @@ -254,7 +254,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_parity_matching(state, diskmax, COMBO2[i].b, buffer, buffer_recov)) return 0; - fprintf(stdlog, "error:%u:%s/%s: Data error\n", pos, lev_config_name(COMBO2[i].a), lev_config_name(COMBO2[i].b)); + fprintf(stdlog, "parity_error:%u:%s/%s: Data error\n", pos, lev_config_name(COMBO2[i].a), lev_config_name(COMBO2[i].b)); ++error; } } @@ -276,7 +276,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_hash_matching(state, rehash, diskmax, failed, failed_map, failed_count, buffer, buffer_zero)) return 0; - fprintf(stdlog, "error:%u:%s/%s: Data error\n", pos, lev_config_name(COMBO2[i].a), lev_config_name(COMBO2[i].b)); + fprintf(stdlog, "parity_error:%u:%s/%s: Data error\n", pos, lev_config_name(COMBO2[i].a), lev_config_name(COMBO2[i].b)); ++error; } } @@ -298,7 +298,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_parity_matching(state, diskmax, COMBO3[i].c, buffer, buffer_recov)) return 0; - fprintf(stdlog, "error:%u:%s/%s/%s: Data error\n", pos, lev_config_name(COMBO3[i].a), lev_config_name(COMBO3[i].b), lev_config_name(COMBO3[i].c)); + fprintf(stdlog, "parity_error:%u:%s/%s/%s: Data error\n", pos, lev_config_name(COMBO3[i].a), lev_config_name(COMBO3[i].b), lev_config_name(COMBO3[i].c)); ++error; } } @@ -321,7 +321,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_hash_matching(state, rehash, diskmax, failed, failed_map, failed_count, buffer, buffer_zero)) return 0; - fprintf(stdlog, "error:%u:%s/%s/%s: Data error\n", pos, lev_config_name(COMBO3[i].a), lev_config_name(COMBO3[i].b), lev_config_name(COMBO3[i].c)); + fprintf(stdlog, "parity_error:%u:%s/%s/%s: Data error\n", pos, lev_config_name(COMBO3[i].a), lev_config_name(COMBO3[i].b), lev_config_name(COMBO3[i].c)); ++error; } } @@ -344,7 +344,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_parity_matching(state, diskmax, COMBO4[i].d, buffer, buffer_recov)) return 0; - fprintf(stdlog, "error:%u:%s/%s/%s/%s: Data error\n", pos, lev_config_name(COMBO4[i].a), lev_config_name(COMBO4[i].b), lev_config_name(COMBO4[i].c), lev_config_name(COMBO4[i].d)); + fprintf(stdlog, "parity_error:%u:%s/%s/%s/%s: Data error\n", pos, lev_config_name(COMBO4[i].a), lev_config_name(COMBO4[i].b), lev_config_name(COMBO4[i].c), lev_config_name(COMBO4[i].d)); ++error; } } @@ -368,7 +368,7 @@ static int repair_step(struct snapraid_state* state, int rehash, unsigned pos, u if (is_hash_matching(state, rehash, diskmax, failed, failed_map, failed_count, buffer, buffer_zero)) return 0; - fprintf(stdlog, "error:%u:%s/%s/%s/%s: Data error\n", pos, lev_config_name(COMBO4[i].a), lev_config_name(COMBO4[i].b), lev_config_name(COMBO4[i].c), lev_config_name(COMBO4[i].d)); + fprintf(stdlog, "parity_error:%u:%s/%s/%s/%s: Data error\n", pos, lev_config_name(COMBO4[i].a), lev_config_name(COMBO4[i].b), lev_config_name(COMBO4[i].c), lev_config_name(COMBO4[i].d)); ++error; } } @@ -899,7 +899,7 @@ static int state_check_process(struct snapraid_state* state, int check, int fix, if (ret == -1) { buffer_recov[l] = 0; /* no parity to use */ - fprintf(stdlog, "error:%u:%s: Read error\n", i, lev_config_name(l)); + fprintf(stdlog, "parity_error:%u:%s: Read error\n", i, lev_config_name(l)); ++error; } } else { @@ -953,7 +953,7 @@ static int state_check_process(struct snapraid_state* state, int check, int fix, if (buffer_recov[l] != 0 && memcmp(buffer_recov[l], buffer[diskmax + l], state->block_size) != 0) { buffer_recov[l] = 0; - fprintf(stdlog, "error:%u:%s: Data error\n", i, lev_config_name(l)); + fprintf(stdlog, "parity_error:%u:%s: Data error\n", i, lev_config_name(l)); ++error; } } @@ -1017,7 +1017,7 @@ static int state_check_process(struct snapraid_state* state, int check, int fix, goto bail; } - fprintf(stdlog, "fixed:%u:%s: Fixed data error\n", i, lev_config_name(l)); + fprintf(stdlog, "parity_fixed:%u:%s: Fixed data error\n", i, lev_config_name(l)); ++recovered_error; } } diff --git a/dry.c b/dry.c index 8334765f..efa498dd 100644 --- a/dry.c +++ b/dry.c @@ -103,7 +103,7 @@ static int state_dry_process(struct snapraid_state* state, struct snapraid_parit if (parity[l]) { ret = parity_read(parity[l], i, buffer_aligned, state->block_size, stdlog); if (ret == -1) { - fprintf(stdlog, "error:%u:%s: Read error\n", i, lev_config_name(l)); + fprintf(stdlog, "parity_error:%u:%s: Read error\n", i, lev_config_name(l)); ++error; } } diff --git a/scrub.c b/scrub.c index 32b24c1d..49bdd6ee 100644 --- a/scrub.c +++ b/scrub.c @@ -219,6 +219,7 @@ static int state_scrub_process(struct snapraid_state* state, struct snapraid_par if (ret == -1) { /* This one is really an unexpected error, because we are only reading */ /* and closing a descriptor should never fail */ + fprintf(stdlog, "error:%u:%s:%s: Close error. %s\n", i, handle[j].disk->name, handle[j].file->sub, strerror(errno)); fprintf(stderr, "DANGER! Unexpected close error in a data disk, it isn't possible to scrub.\n"); printf("Stopping at block %u\n", i); ++error; @@ -228,7 +229,7 @@ static int state_scrub_process(struct snapraid_state* state, struct snapraid_par ret = handle_open(&handle[j], block_file_get(block), state->opt.skip_sequential, stderr); if (ret == -1) { - fprintf(stdlog, "error:%u:%s:%s: Open error at position %u\n", i, handle[j].disk->name, block_file_get(block)->sub, block_file_pos(block)); + fprintf(stdlog, "error:%u:%s:%s: Open error. %s\n", i, handle[j].disk->name, handle[j].file->sub, strerror(errno)); ++error; error_on_this_block = 1; continue; @@ -251,7 +252,7 @@ static int state_scrub_process(struct snapraid_state* state, struct snapraid_par read_size = handle_read(&handle[j], block, buffer[j], state->block_size, stderr); if (read_size == -1) { - fprintf(stdlog, "error:%u:%s:%s: Read error at position %u\n", i, handle[j].disk->name, block_file_get(block)->sub, block_file_pos(block)); + fprintf(stdlog, "error:%u:%s:%s: Read error at position %u\n", i, handle[j].disk->name, handle[j].file->sub, block_file_pos(block)); ++error; error_on_this_block = 1; continue; @@ -273,7 +274,7 @@ static int state_scrub_process(struct snapraid_state* state, struct snapraid_par if (block_has_updated_hash(block)) { /* compare the hash */ if (memcmp(hash, block->hash, HASH_SIZE) != 0) { - fprintf(stdlog, "error:%u:%s:%s: Data error at position %u\n", i, handle[j].disk->name, block_file_get(block)->sub, block_file_pos(block)); + fprintf(stdlog, "error:%u:%s:%s: Data error at position %u\n", i, handle[j].disk->name, handle[j].file->sub, block_file_pos(block)); /* it's a silent error only if we are dealing with synched files */ if (file_is_unsynched) { @@ -281,7 +282,7 @@ static int state_scrub_process(struct snapraid_state* state, struct snapraid_par error_on_this_block = 1; } else { fprintf(stderr, "Data error in file '%s' at position '%u'\n", handle[j].path, block_file_pos(block)); - fprintf(stderr, "DANGER! Unexpected data error in a data disk! The block is now marked as bad!\n"); + fprintf(stderr, "WARNING! Unexpected data error in a data disk! The block is now marked as bad!\n"); fprintf(stderr, "Try with 'snapraid -e fix' to recover!\n"); ++silent_error; @@ -318,7 +319,6 @@ static int state_scrub_process(struct snapraid_state* state, struct snapraid_par /* compare the parity */ for(l=0;llevel;++l) { - if (buffer_recov[l] && memcmp(buffer[diskmax + l], buffer_recov[l], state->block_size) != 0) { fprintf(stdlog, "parity_error:%u:%s: Data error\n", i, lev_config_name(l)); diff --git a/sync.c b/sync.c index 15cf888b..175b673c 100644 --- a/sync.c +++ b/sync.c @@ -230,7 +230,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari if (ret == -1) { /* This one is really an unexpected error, because we are only reading */ /* and closing a descriptor should never fail */ + fprintf(stdlog, "error:%u:%s:%s: Close error. %s\n", i, handle[j].disk->name, handle[j].file->sub, strerror(errno)); fprintf(stderr, "DANGER! Unexpected close error in a data disk, it isn't possible to sync.\n"); + fprintf(stderr, "Ensure that disk '%s' is sane and that file '%s' can be accessed.\n", handle[j].disk->dir, handle[j].path); printf("Stopping at block %u\n", i); ++error; goto bail; @@ -240,8 +242,10 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari ret = handle_open(&handle[j], block_file_get(block), state->opt.skip_sequential, stderr); if (ret == -1) { if (errno == ENOENT) { + fprintf(stdlog, "error:%u:%s:%s: Open missing error\n", i, handle[j].disk->name, handle[j].file->sub); fprintf(stderr, "Missing file '%s'.\n", handle[j].path); - fprintf(stderr, "WARNING! You cannot modify data disk during a sync. Rerun the sync command when finished.\n"); + fprintf(stderr, "WARNING! You cannot modify data disk during a sync.\n"); + fprintf(stderr, "Rerun the sync command when finished.\n"); ++error; @@ -250,12 +254,21 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari error_on_this_block = 1; continue; } else if (errno == EACCES) { + fprintf(stdlog, "error:%u:%s:%s: Open access error\n", i, handle[j].disk->name, handle[j].file->sub); fprintf(stderr, "No access at file '%s'.\n", handle[j].path); fprintf(stderr, "WARNING! Please fix the access permission in the data disk.\n"); - printf("Stopping at block %u\n", i); + fprintf(stderr, "Rerun the sync command when finished.\n"); + + ++error; + + /* this isn't a serious error, so we skip this block, and continue with others */ + error_on_this_block = 1; + continue; } else { + fprintf(stdlog, "error:%u:%s:%s: Open error. %s\n", i, handle[j].disk->name, handle[j].file->sub, strerror(errno)); fprintf(stderr, "DANGER! Unexpected open error in a data disk, it isn't possible to sync.\n"); - printf("Stopping to allow recovery. Try with 'snapraid check'\n"); + fprintf(stderr, "Ensure that disk '%s' is sane and that file '%s' can be accessed.\n", handle[j].disk->dir, handle[j].path); + printf("Stopping to allow recovery. Try with 'snapraid check -f %s'\n", handle[j].file->sub); } ++error; @@ -268,6 +281,7 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari || STAT_NSEC(&handle[j].st) != block_file_get(block)->mtime_nsec || handle[j].st.st_ino != block_file_get(block)->inode ) { + fprintf(stdlog, "error:%u:%s:%s: Unexpected change\n", i, handle[j].disk->name, handle[j].file->sub); if (handle[j].st.st_size != block_file_get(block)->size) fprintf(stderr, "Unexpected size change at file '%s'.\n", handle[j].path); else if (handle[j].st.st_mtime != block_file_get(block)->mtime_sec @@ -275,7 +289,8 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari fprintf(stderr, "Unexpected time change at file '%s'.\n", handle[j].path); else fprintf(stderr, "Unexpected inode change from %"PRIu64" to %"PRIu64" at file '%s'.\n", block_file_get(block)->inode, (uint64_t)handle[j].st.st_ino, handle[j].path); - fprintf(stderr, "WARNING! You cannot modify files during a sync. Rerun the sync command when finished.\n"); + fprintf(stderr, "WARNING! You cannot modify files during a sync.\n"); + fprintf(stderr, "Rerun the sync command when finished.\n"); ++error; @@ -287,8 +302,10 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari read_size = handle_read(&handle[j], block, buffer[j], state->block_size, stderr); if (read_size == -1) { + fprintf(stdlog, "error:%u:%s:%s: Read error at position %u\n", i, handle[j].disk->name, handle[j].file->sub, block_file_pos(block)); fprintf(stderr, "DANGER! Unexpected read error in a data disk, it isn't possible to sync.\n"); - printf("Stopping to allow recovery. Try with 'snapraid check'\n"); + fprintf(stderr, "Ensure that disk '%s' is sane and that file '%s' can be read.\n", handle[j].disk->dir, handle[j].path); + printf("Stopping to allow recovery. Try with 'snapraid check -f %s'\n", handle[j].file->sub); ++error; goto bail; } @@ -309,9 +326,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari if (block_has_updated_hash(block)) { /* compare the hash */ if (memcmp(hash, block->hash, HASH_SIZE) != 0) { - fprintf(stdlog, "error:%u:%s:%s: Data error at position %u\n", i, handle[j].disk->name, block_file_get(block)->sub, block_file_pos(block)); - fprintf(stderr, "Data error in file '%s' at position '%u'\n", handle[j].path, block_file_pos(block)); - fprintf(stderr, "DANGER! Unexpected data error in a data disk! The block is now marked as bad!\n"); + fprintf(stdlog, "error:%u:%s:%s: Data error at position %u\n", i, handle[j].disk->name, handle[j].file->sub, block_file_pos(block)); + fprintf(stderr, "Data error at file '%s' at position '%u'\n", handle[j].path, block_file_pos(block)); + fprintf(stderr, "WARNING! Unexpected data error in a data disk! The block is now marked as bad!\n"); fprintf(stderr, "Try with 'snapraid -e fix' to recover!\n"); /* silent errors are very rare, and are not a signal that a disk */ @@ -363,7 +380,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari for(l=0;llevel;++l) { ret = parity_write(parity[l], i, buffer[diskmax+l], state->block_size); if (ret == -1) { + fprintf(stdlog, "parity_error:%u:%s: Write error\n", i, lev_config_name(l)); fprintf(stderr, "DANGER! Write error in the %s disk, it isn't possible to sync.\n", lev_name(l)); + fprintf(stderr, "Ensure that disk '%s' is sane.\n", lev_config_name(l)); printf("Stopping at block %u\n", i); ++error; goto bail;