diff --git a/cdrskin/cdrskin_timestamp.h b/cdrskin/cdrskin_timestamp.h index bab1f26..dbe3f95 100644 --- a/cdrskin/cdrskin_timestamp.h +++ b/cdrskin/cdrskin_timestamp.h @@ -1 +1 @@ -#define Cdrskin_timestamP "2019.04.17.095742" +#define Cdrskin_timestamP "2019.07.05.133618" diff --git a/libburn/libdax_msgs.h b/libburn/libdax_msgs.h index 16bfca2..5b5c403 100644 --- a/libburn/libdax_msgs.h +++ b/libburn/libdax_msgs.h @@ -615,6 +615,7 @@ Range "scdbackup" : 0x00020000 to 0x0002ffff 0x000201aa (FAILURE,HIGH) = No CD-TEXT packs in file 0x000201ab (WARN,HIGH) = Leaving burn_source_fifo object undisposed 0x000201ac (NOTE,HIGH) = Drive currently does not offer Stream Recording + 0x000201ad (NOTE,HIGH) = WRITE commands have been repeated libdax_audioxtr: diff --git a/libburn/mmc.c b/libburn/mmc.c index 3e46c9e..7904cf3 100644 --- a/libburn/mmc.c +++ b/libburn/mmc.c @@ -643,7 +643,8 @@ void mmc_close(struct burn_drive *d, int session, int track) d->cancel = 1; return; } - if (spc_wait_unit_attention(d, 3600, "CLOSE TRACK SESSION", 0) <= 0) + spc_human_readable_cmd(c, msg, 160, 0); + if (spc_wait_unit_attention(d, 3600, msg, 0) <= 0) d->cancel = 1; } @@ -964,7 +965,7 @@ fprintf(stderr, "libburn_DEBUG: buffer sectors= %d bytes= %d\n", /* ts A70215 */ if (d->media_lba_limit > 0 && start >= d->media_lba_limit) { - msg = calloc(1, 160); + msg = calloc(1, 320); if (msg != NULL) { sprintf(msg, "Exceeding range of permissible write addresses (%d >= %d)", @@ -973,6 +974,15 @@ fprintf(stderr, "libburn_DEBUG: buffer sectors= %d bytes= %d\n", 0x0002012d, LIBDAX_MSGS_SEV_FATAL, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + strcpy(msg, "CDB= "); + if (spc_human_readable_cmd(c, msg + strlen(msg), + 320 - strlen(msg), 1) > 0) { + libdax_msgs_submit(libdax_messenger, + d->global_index, 0x0002012d, + LIBDAX_MSGS_SEV_FATAL, + LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); + } free(msg); } d->cancel = 1; /* No need for mutexing because atomic */ @@ -1030,7 +1040,7 @@ fprintf(stderr, "libburn_DEBUG: buffer sectors= %d bytes= %d\n", int key, asc, ascq; int err_sev = LIBDAX_MSGS_SEV_FATAL; - msg = calloc(1, 256); + msg = calloc(1, 320); if (msg != NULL) { sprintf(msg, "SCSI error on write(%d,%d): ", start, len); @@ -1059,12 +1069,21 @@ fprintf(stderr, "libburn_DEBUG: buffer sectors= %d bytes= %d\n", 0x0002011d, err_sev, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + strcpy(msg, "CDB= "); + if (spc_human_readable_cmd(c, msg + strlen(msg), + 320 - strlen(msg), 0) > 0) { + libdax_msgs_submit(libdax_messenger, + d->global_index, 0x0002011d, + err_sev, LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); + } free(msg); } d->cancel = 1; return BE_CANCELLED; - } + } + d->write_retry_count += c->retry_count; return 0; } @@ -3566,7 +3585,8 @@ void mmc_sync_cache(struct burn_drive *d) goto ex; } - if (spc_wait_unit_attention(d, 3600, "SYNCHRONIZE CACHE", 0) <= 0) + spc_human_readable_cmd(c, msg, 160, 0); + if (spc_wait_unit_attention(d, 3600, msg, 0) <= 0) d->cancel = 1; else d->needs_sync_cache = 0; diff --git a/libburn/sg-freebsd-port.c b/libburn/sg-freebsd-port.c index 3a347ce..4953f90 100644 --- a/libburn/sg-freebsd-port.c +++ b/libburn/sg-freebsd-port.c @@ -567,6 +567,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) ccb->csio.dxfer_len = 0; } + /* ts B90523 : Record effective transfer length request for debugging*/ + c->dxfer_len = ccb->csio.dxfer_len; + do { memset(&ccb->csio.sense_data, 0, sizeof(ccb->csio.sense_data)); err = cam_send_ccb(d->cam, ccb); @@ -585,6 +588,7 @@ int sg_issue_command(struct burn_drive *d, struct command *c) } /* XXX */ memcpy(c->sense, &ccb->csio.sense_data, ccb->csio.sense_len); + c->sense_len = ccb->csio.sense_len; if ((ccb->ccb_h.status & CAM_STATUS_MASK) != CAM_REQ_CMP) { if (!c->retry) { c->error = 1; @@ -603,6 +607,8 @@ int sg_issue_command(struct burn_drive *d, struct command *c) } else { done = 1; } + if (!done) + spc_register_retry(c); } while (!done); cam_freeccb(ccb); return 1; diff --git a/libburn/sg-freebsd.c b/libburn/sg-freebsd.c index 035b878..99f1f50 100644 --- a/libburn/sg-freebsd.c +++ b/libburn/sg-freebsd.c @@ -873,6 +873,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) ccb->csio.dxfer_len = 0; } + /* ts B90523 : Record effective transfer length request for debugging*/ + c->dxfer_len = ccb->csio.dxfer_len; + start_time = time(NULL); for (i = 0; !done; i++) { @@ -985,6 +988,8 @@ int sg_issue_command(struct burn_drive *d, struct command *c) timeout_ms, i, !!ignore_error); if (d->cancel) done = 1; + if (!done) + spc_register_retry(c); } while (!done); ret = 1; ex:; diff --git a/libburn/sg-libcdio.c b/libburn/sg-libcdio.c index f7bb1e3..394a7ba 100644 --- a/libburn/sg-libcdio.c +++ b/libburn/sg-libcdio.c @@ -665,6 +665,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) e_direction = SCSI_MMC_DATA_NONE; } + /* ts B90523 : Record effective transfer length request for debugging*/ + c->dxfer_len = dxfer_len; + /* retry-loop */ start_time = time(NULL); if (c->timeout > 0) @@ -728,6 +731,8 @@ int sg_issue_command(struct burn_drive *d, struct command *c) start_time, timeout_ms, i, 0); if (d->cancel) done = 1; + if (!done) + spc_register_retry(c); } /* end of retry-loop */ diff --git a/libburn/sg-linux.c b/libburn/sg-linux.c index 48c29c7..10cdd3c 100644 --- a/libburn/sg-linux.c +++ b/libburn/sg-linux.c @@ -1945,9 +1945,15 @@ static int evaluate_transport_success(struct burn_drive *d, struct command *c, (unsigned int) host_status, host_problem); sev = LIBDAX_MSGS_SEV_FAILURE; if (do_retry && !give_up_drive) - sev = LIBDAX_MSGS_SEV_DEBUG; + sev = LIBDAX_MSGS_SEV_NOTE; libdax_msgs_submit(libdax_messenger, d->global_index, 0x000201a7, sev, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + strcpy(msg, "Command: "); + if (spc_human_readable_cmd(c, msg + strlen(msg), + 160 - strlen(msg), 0) > 0) + libdax_msgs_submit(libdax_messenger, d->global_index, + 0x000201a7, sev, LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); sprintf(msg, "--- SG_IO: host_status= 0x%x %s", (unsigned int) host_status, host_problem); scsi_log_message(d, fp, msg, 0); @@ -2001,9 +2007,15 @@ static int evaluate_transport_success(struct burn_drive *d, struct command *c, driver_problem, driver_sugg); sev = LIBDAX_MSGS_SEV_FAILURE; if (do_retry && !give_up_drive) - sev = LIBDAX_MSGS_SEV_DEBUG; + sev = LIBDAX_MSGS_SEV_NOTE; libdax_msgs_submit(libdax_messenger, d->global_index, 0x000201a8, sev, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + strcpy(msg, "Command: "); + if (spc_human_readable_cmd(c, msg + strlen(msg), + 160 - strlen(msg), 0) > 0) + libdax_msgs_submit(libdax_messenger, d->global_index, + 0x000201a8, sev, LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); sprintf(msg, "--- SG_IO: driver_status= 0x%x %s / %s", (unsigned int) driver_status, driver_problem, driver_sugg); @@ -2042,7 +2054,7 @@ static void react_on_drive_loss(struct burn_drive *d, struct command *c, */ int sg_issue_command(struct burn_drive *d, struct command *c) { - int done = 0, no_c_page = 0, i, j, ret; + int done = 0, no_c_page = 0, i, ret; int err; time_t start_time; sg_io_hdr_t s; @@ -2163,6 +2175,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) } s.usr_ptr = c; + /* ts B90523 : Record effective transfer length request for debugging*/ + c->dxfer_len = s.dxfer_len; + start_time = time(NULL); for(i = 0; !done; i++) { @@ -2204,14 +2219,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) d->global_index, 0x0002010c, LIBDAX_MSGS_SEV_FATAL, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); - sprintf(msg, "Attempted command: %s : ", - spc_command_name( - (unsigned int) c->opcode[0], 0)); - for (j = 0; j <16 && j < c->oplen; j++) - sprintf(msg + strlen(msg), "%2.2x ", - c->opcode[j]); - sprintf(msg + strlen(msg), " : dxfer_len= %d", - s.dxfer_len); + sprintf(msg, "Attempted command: "); + spc_human_readable_cmd(c, msg + strlen(msg), + 160 - strlen(msg), 0); libdax_msgs_submit(libdax_messenger, d->global_index, 0x0002010c, LIBDAX_MSGS_SEV_FATAL, LIBDAX_MSGS_PRIO_HIGH, @@ -2235,9 +2245,12 @@ int sg_issue_command(struct burn_drive *d, struct command *c) if (d->cancel) break; /* if ! done : loop for retry */; - if (!done && (burn_sg_log_scsi & 3)) { - scsi_log_text("+++ Repeating command", fp, 0); - scsi_log_cmd(c, fp, 0); + if (!done) { + spc_register_retry(c); + if (burn_sg_log_scsi & 3) { + scsi_log_text("+++ Repeating command", fp, 0); + scsi_log_cmd(c, fp, 0); + } } } diff --git a/libburn/sg-netbsd.c b/libburn/sg-netbsd.c index 5a9207c..22da0fb 100644 --- a/libburn/sg-netbsd.c +++ b/libburn/sg-netbsd.c @@ -587,6 +587,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) req.datalen = 0; } + /* ts B90523 : Record effective transfer length request for debugging*/ + c->dxfer_len = req.datalen; + /* retry-loop */ start_time = time(NULL); for(i = 0; !done; i++) { @@ -668,6 +671,8 @@ if (c->opcode[0] == 0x5a) { start_time, timeout_ms, i, 0); if (d->cancel) done = 1; + if (!done) + spc_register_retry(c); } /* end of retry-loop */ return 1; diff --git a/libburn/sg-solaris.c b/libburn/sg-solaris.c index abfc26c..bdbf54b 100644 --- a/libburn/sg-solaris.c +++ b/libburn/sg-solaris.c @@ -754,6 +754,9 @@ int sg_issue_command(struct burn_drive *d, struct command *c) cgc.uscsi_rqlen = sizeof(c->sense); cgc.uscsi_rqbuf = (caddr_t) c->sense; + /* ts B90523 : Record effective transfer length request for debugging*/ + c->dxfer_len = cgc.uscsi_buflen; + /* retry-loop */ start_time = time(NULL); for(i = 0; !done; i++) { @@ -799,6 +802,8 @@ int sg_issue_command(struct burn_drive *d, struct command *c) start_time, timeout_ms, i, 0); if (d->cancel) done = 1; + if (!done) + spc_register_retry(c); } /* end of retry-loop */ diff --git a/libburn/spc.c b/libburn/spc.c index 3ab207a..e47b877 100644 --- a/libburn/spc.c +++ b/libburn/spc.c @@ -75,10 +75,16 @@ int scsi_init_command(struct command *c, unsigned char *opcode, int oplen) c->dir = NO_TRANSFER; c->dxfer_len = -1; memset(c->sense, 0, sizeof(c->sense)); + c->sense_len = 0; c->error = 0; c->retry = 0; c->page = NULL; c->timeout = Libburn_scsi_default_timeouT; + c->start_time = c->end_time = 0.0; + c->retry_count = 0; + c->last_retry_key = 0; + c->last_retry_asc = 0; + c->last_retry_ascq = 0; return 1; } @@ -153,14 +159,20 @@ int spc_wait_unit_attention(struct burn_drive *d, int max_sec, char *cmd_text, int i, ret = 1, key = 0, asc = 0, ascq = 0, clueless_start = 0; static double tests_per_second = 2.0; int sleep_usecs, loop_limit, clueless_timeout, progress; - char *msg = NULL; + char *msg = NULL, *cmd_name = NULL, *cmd_cpt; unsigned char sense[14]; BURN_ALLOC_MEM(msg, char, 320); + BURN_ALLOC_MEM(cmd_name, char, 320); clueless_timeout = 5 * tests_per_second + 1; loop_limit = max_sec * tests_per_second + 1; sleep_usecs = 1000000 / tests_per_second; + strcpy(cmd_name, cmd_text); + cmd_cpt = strchr(cmd_name, ':'); + if (cmd_cpt != NULL) + *cmd_cpt = 0; + if (!(flag & 1)) usleep(sleep_usecs); @@ -190,7 +202,7 @@ int spc_wait_unit_attention(struct burn_drive *d, int max_sec, char *cmd_text, handle_error:; /* ts A90213 */ sprintf(msg, - "Asynchronous SCSI error on %s: ", cmd_text); + "Asynchronous SCSI error on %s: ", cmd_name); sense[0] = 0x70; /* Fixed format sense data */ sense[2] = key; sense[12] = asc; @@ -201,6 +213,14 @@ handle_error:; 0x0002014d, LIBDAX_MSGS_SEV_SORRY, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + if (cmd_cpt != NULL) { + sprintf(msg, "Attempted SCSI CDB: %s", + cmd_cpt + 1); + libdax_msgs_submit(libdax_messenger, + d->global_index, 0x0002014d, + LIBDAX_MSGS_SEV_SORRY, LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); + } d->cancel = 1; break; } else if (ascq == 0x00) { /* CAUSE NOT REPORTABLE */ @@ -214,6 +234,16 @@ handle_error:; LIBDAX_MSGS_SEV_DEBUG, LIBDAX_MSGS_PRIO_HIGH, "Ended clueless NOT READY cycle", 0, 0); + if (cmd_cpt != NULL) { + sprintf(msg, "Attempted SCSI CDB: %s", + cmd_cpt + 1); + libdax_msgs_submit(libdax_messenger, + d->global_index, + 0x00000002, + LIBDAX_MSGS_SEV_DEBUG, + LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); + } ret = 1; /* medium not present = ok */ break; } @@ -225,7 +255,7 @@ slumber:; } if (ret <= 0 || !(flag & 2)) { sprintf(msg, "Async %s %s after %d.%d seconds", - cmd_text, (ret > 0 ? "succeeded" : "failed"), + cmd_name, (ret > 0 ? "succeeded" : "failed"), i / 10, i % 10); libdax_msgs_submit(libdax_messenger, d->global_index, 0x00020150, LIBDAX_MSGS_SEV_DEBUG, @@ -236,12 +266,19 @@ slumber:; {ret = (ret > 0); goto ex;} sprintf(msg, "Timeout (%d s) with asynchronous SCSI command %s\n", - max_sec, cmd_text); + max_sec, cmd_name); libdax_msgs_submit(libdax_messenger, d->global_index, 0x0002014f, LIBDAX_MSGS_SEV_SORRY, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + if (cmd_cpt != NULL) { + sprintf(msg, "Attempted SCSI CDB: %s", cmd_cpt + 1); + libdax_msgs_submit(libdax_messenger, d->global_index, + 0x0002014f, LIBDAX_MSGS_SEV_SORRY, + LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + } ret = 0; ex:; BURN_FREE_MEM(msg); + BURN_FREE_MEM(cmd_name); return ret; } @@ -1727,6 +1764,60 @@ char *spc_command_name(unsigned int c, int flag) } +/* ts B90616 */ +void spc_register_retry(struct command *c) +{ + c->retry_count++; + spc_decode_sense(c->sense, c->sense_len, &c->last_retry_key, + &c->last_retry_asc, &c->last_retry_ascq); +} + + +/* ts B90511 */ +/* @param flag bit0= do not prepend command name + bit1= do not append dxfer_len +*/ +int spc_human_readable_cmd(struct command *c, char *msg, int msg_max, int flag) +{ + int j, l, lname; + + if ((flag & 1) && c->retry_count <= 0) { + msg[0] = 0; + } else { + if (msg_max < 60) + return -1; + strcpy(msg, spc_command_name( (unsigned int) c->opcode[0], 0)); + if (c->retry_count > 0) { + sprintf(msg + strlen(msg), " #%d", c->retry_count + 1); + if (c->last_retry_key > 0) + sprintf(msg + strlen(msg), ",[%X %2.2X %2.2X]", + c->last_retry_key, c->last_retry_asc, + c->last_retry_ascq); + } + strcat(msg, " : "); + } + lname = l = strlen(msg); + for (j = 0; j < 16 && j < c->oplen; j++) { + if (l > msg_max - 3) { + if (msg_max - 4 >= lname) { + l = msg_max - 4; + sprintf(msg + strlen(msg), "... "); + } + return 0; + } + sprintf(msg + l, "%2.2x ", c->opcode[j]); + l += 3; + } + if (c->dir != NO_TRANSFER && c->page != NULL && !(flag & 2)) { + if (l > msg_max - 24) + return 0; + sprintf(msg + l, " : dxfer_len= %d", c->dxfer_len); + l = strlen(msg); + } + return 1; +} + + /* ts A61030 - A61115 */ /* @param flag bit0= do report conditions which are considered not an error bit1= report with severity FAILURE rather than DEBUG @@ -1764,7 +1855,16 @@ int scsi_notify_error(struct burn_drive *d, struct command *c, ret = libdax_msgs_submit(libdax_messenger, d->global_index, 0x0002010f, (flag & 2) && d->silent_on_scsi_error != 3 ? LIBDAX_MSGS_SEV_FAILURE : LIBDAX_MSGS_SEV_DEBUG, - LIBDAX_MSGS_PRIO_HIGH, msg,0,0); + LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + strcpy(msg, "CDB= "); + if (spc_human_readable_cmd(c, msg + strlen(msg), 320 - strlen(msg), 1) + > 0) { + libdax_msgs_submit(libdax_messenger, d->global_index, + 0x0002010f, + (flag & 2) && d->silent_on_scsi_error != 3 ? + LIBDAX_MSGS_SEV_FAILURE : LIBDAX_MSGS_SEV_DEBUG, + LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + } ex:; BURN_FREE_MEM(msg); BURN_FREE_MEM(scsi_msg); @@ -2011,6 +2111,8 @@ int scsi_eval_cmd_outcome(struct burn_drive *d, struct command *c, void *fp, if (burn_sg_log_scsi & 3) scsi_log_err(d, c, fp, sense, sense_len, (sense_len > 0) | (flag & 2)); + if (sense == c->sense) + c->sense_len = sense_len; if (sense_len <= 0) {done = 1; goto ex;} @@ -2042,6 +2144,13 @@ int scsi_eval_cmd_outcome(struct burn_drive *d, struct command *c, void *fp, 0x0002018a, LIBDAX_MSGS_SEV_SORRY, LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); + strcpy(msg, "Command: "); + if (spc_human_readable_cmd(c, msg + strlen(msg), + 320 - strlen(msg), 0) > 0) + libdax_msgs_submit(libdax_messenger, + d->global_index, 0x0002018a, + LIBDAX_MSGS_SEV_SORRY, + LIBDAX_MSGS_PRIO_HIGH, msg, 0, 0); goto err_ex; } if (d->cancel) diff --git a/libburn/spc.h b/libburn/spc.h index 57beffa..9fe75df 100644 --- a/libburn/spc.h +++ b/libburn/spc.h @@ -117,6 +117,13 @@ int spc_decode_sense(unsigned char *sense, int senselen, /* ts B90206 */ char *spc_command_name(unsigned int c, int flag); +/* ts B90511 */ +int spc_human_readable_cmd(struct command *c, char *msg, int msg_max, + int flag); + +/* ts B90616 */ +void spc_register_retry(struct command *c); + /* ts B00808 */ /** Evaluates outcome of a single SCSI command, eventually logs sense data, and issues DEBUG error message in case the command is evaluated as done. diff --git a/libburn/transport.h b/libburn/transport.h index 0abe71e..cfe3033 100644 --- a/libburn/transport.h +++ b/libburn/transport.h @@ -61,6 +61,7 @@ struct command int dir; int dxfer_len; unsigned char sense[128]; + int sense_len; int error; int retry; struct buffer *page; @@ -69,6 +70,10 @@ struct command double start_time; double end_time; + int retry_count; + int last_retry_key; + int last_retry_asc; + int last_retry_ascq; }; struct burn_scsi_inquiry_data @@ -430,6 +435,8 @@ struct burn_drive /* ts B00225 */ pthread_t thread_tid; + /* ts B90513 */ + unsigned int write_retry_count; /* transport functions */ int (*grab) (struct burn_drive *); diff --git a/libburn/write.c b/libburn/write.c index bd65602..029c253 100644 --- a/libburn/write.c +++ b/libburn/write.c @@ -1379,6 +1379,7 @@ int burn_disc_init_write_status(struct burn_write_opts *o, ret = burn_write_opts_clone(o, &(d->write_opts), 0); if (ret <= 0) return ret; + d->write_retry_count = 0; d->busy = BURN_DRIVE_WRITING; @@ -3194,6 +3195,14 @@ ex:; burn_write_opts_free(d->write_opts); d->write_opts = NULL; } + if (d->write_retry_count > 0) { + sprintf(msg, "WRITE command repetition happened %u times", + d->write_retry_count); + libdax_msgs_submit(libdax_messenger, d->global_index, + 0x000201ad, + LIBDAX_MSGS_SEV_NOTE, LIBDAX_MSGS_PRIO_HIGH, + msg, 0, 0); + } return; }