Showing more info in case of drive errors and transport problems

cdrskin/cdrskin_timestamp.h

@@ -1 +1 @@
-#define Cdrskin_timestamP "2019.04.17.095742"
+#define Cdrskin_timestamP "2019.07.05.133618"

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:

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;

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;

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:;

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 */
 

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 : ",
+			sprintf(msg, "Attempted command: ");
-				spc_command_name(
+			spc_human_readable_cmd(c, msg + strlen(msg),
-					(unsigned int) c->opcode[0], 0));
+					       160 - strlen(msg), 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);
 			libdax_msgs_submit(libdax_messenger,
 				 d->global_index, 0x0002010c,
 				 LIBDAX_MSGS_SEV_FATAL, LIBDAX_MSGS_PRIO_HIGH,
@@ -2235,11 +2245,14 @@ 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)) {
+		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);
 			}
 		}
+	}
 
 	ret = 1;
 ex:;

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;

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 */
 

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)

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.

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 *);

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;
 }