Re: Bug#733565: SIX messages per on boot console should be TWO

Re: Bug#733565: SIX messages per on boot console should be TWO

[Ben Hutchings]

[-- Attachment #1: Type: text/plain, Size: 1739 bytes --]

Control: reassign -1 src:linux 3.12.6-1

On Mon, 2013-12-30 at 07:13 +0800, jidanni@jidanni.org wrote:
> Package: linux-image-3.12-1-686-pae
> 
> Currently any such devices as below that are attached during boot still
> produce the below SIX messages per device when they should only produce
> TWO:
> 
> # dmesg |egrep Caching\|Assuming
> [    3.960663] sd 3:0:0:0: [sdb] No Caching mode page found
> [    3.960701] sd 3:0:0:0: [sdb] Assuming drive cache: write through
> [    3.978659] sd 3:0:0:0: [sdb] No Caching mode page found
> [    3.978694] sd 3:0:0:0: [sdb] Assuming drive cache: write through
> [    3.998652] sd 3:0:0:0: [sdb] No Caching mode page found
> [    3.998689] sd 3:0:0:0: [sdb] Assuming drive cache: write through
> [    4.174630] sd 2:0:0:2: [sde] No Caching mode page found
> [    4.174669] sd 2:0:0:2: [sde] Assuming drive cache: write through
> [    4.196628] sd 2:0:0:2: [sde] No Caching mode page found
> [    4.196664] sd 2:0:0:2: [sde] Assuming drive cache: write through
> [    4.220624] sd 2:0:0:2: [sde] No Caching mode page found
> [    4.220661] sd 2:0:0:2: [sde] Assuming drive cache: write through
> 
> Please confirm that you also see the six messages right there on the
> console stderr.

I'm not seeing it at all here as my SSD apparently does implement the
caching mode page.

I can see that it is emitted by sd_read_cache_type(), which is called by
sd_revalidate_disk(), and that is apparently now called 3 times during
probe.  Which is quite ridiculous.

And I wonder whether this situation (no caching mode page) is really
serious enough to deserve logging at ERR severity?

Ben.

-- 
Ben Hutchings
Logic doesn't apply to the real world. - Marvin Minsky

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: Bug#733565: SIX messages per on boot console should be TWO

[Martin K. Petersen]

>>>>> "Ben" == Ben Hutchings <ben@decadent.org.uk> writes:

Ben> I can see that it is emitted by sd_read_cache_type(), which is
Ben> called by sd_revalidate_disk(), and that is apparently now called 3
Ben> times during probe.  Which is quite ridiculous.

We have to discover the basics of the disk before we can create the
gendisk/block device/request queue. And some of the subsequent
parameters we need can't be stored or acted upon until everything has
been set up. So some questions we have to ask several times.


Ben> And I wonder whether this situation (no caching mode page) is
Ben> really serious enough to deserve logging at ERR severity?

I guess we could extend the first_scan logic to cover the error case
scenarios. But it is quite unusual for a device to not implement the
caching mode page...

-- 
Martin K. Petersen	Oracle Linux Engineering

Re: Bug#733565: SIX messages per on boot console should be TWO

[jidanni]

>>>>> "MKP" == Martin K Petersen <martin.petersen@oracle.com> writes:

MKP> We have to discover the basics of the disk before we can create the
MKP> gendisk/block device/request queue. And some of the subsequent
MKP> parameters we need can't be stored or acted upon until everything has
MKP> been set up. So some questions we have to ask several times.

Perhaps the messages could be each differentiated so the user doesn't see
them as something that looks like a bug and needs to be reported.

E.g., prefix/suffix with PHASE I CHECK, PHASE II CHECK, PHASE III CHECK.
or FIRST CHECK, INTERMEDIATE CHECK, FINAL CHECK,
or CHECK 1, CHECK 2...
or INTERMEDIATE PROBE:, FINAL PROBE:, etc.

Re: Bug#733565: SIX messages per on boot console should be TWO

[Martin K. Petersen]

>>>>> "Martin" == Martin K Petersen <martin.petersen@oracle.com> writes:

Martin> I guess we could extend the first_scan logic to cover the error
Martin> case scenarios.

[SCSI] sd: Quiesce mode sense error messages

Messages about discovered disk properties are only printed once unless
they are found to have changed. Errors encountered during mode sense,
however, are printed every time we revalidate.

Quiesce mode sense errors so they are only printed during the first
scan.

Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>

diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index 69725f7c32c1..14d601ed1956 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -2283,7 +2283,7 @@ sd_read_write_protect_flag(struct scsi_disk *sdkp, unsigned char *buffer)
 
 	set_disk_ro(sdkp->disk, 0);
 	if (sdp->skip_ms_page_3f) {
-		sd_printk(KERN_NOTICE, sdkp, "Assuming Write Enabled\n");
+		sd_first_printk(KERN_NOTICE, sdkp, "Assuming Write Enabled\n");
 		return;
 	}
 
@@ -2315,7 +2315,7 @@ sd_read_write_protect_flag(struct scsi_disk *sdkp, unsigned char *buffer)
 	}
 
 	if (!scsi_status_is_good(res)) {
-		sd_printk(KERN_WARNING, sdkp,
+		sd_first_printk(KERN_WARNING, sdkp,
 			  "Test WP failed, assume Write Enabled\n");
 	} else {
 		sdkp->write_prot = ((data.device_specific & 0x80) != 0);
@@ -2383,7 +2383,8 @@ sd_read_cache_type(struct scsi_disk *sdkp, unsigned char *buffer)
 	if (!data.header_length) {
 		modepage = 6;
 		first_len = 0;
-		sd_printk(KERN_ERR, sdkp, "Missing header in MODE_SENSE response\n");
+		sd_first_printk(KERN_ERR, sdkp,
+				"Missing header in MODE_SENSE response\n");
 	}
 
 	/* that went OK, now ask for the proper length */
@@ -2396,7 +2397,7 @@ sd_read_cache_type(struct scsi_disk *sdkp, unsigned char *buffer)
 	if (len < 3)
 		goto bad_sense;
 	else if (len > SD_BUF_SIZE) {
-		sd_printk(KERN_NOTICE, sdkp, "Truncating mode parameter "
+		sd_first_printk(KERN_NOTICE, sdkp, "Truncating mode parameter "
 			  "data from %d to %d bytes\n", len, SD_BUF_SIZE);
 		len = SD_BUF_SIZE;
 	}
@@ -2419,8 +2420,9 @@ sd_read_cache_type(struct scsi_disk *sdkp, unsigned char *buffer)
 				/* We're interested only in the first 3 bytes.
 				 */
 				if (len - offset <= 2) {
-					sd_printk(KERN_ERR, sdkp, "Incomplete "
-						  "mode parameter data\n");
+					sd_first_printk(KERN_ERR, sdkp,
+						"Incomplete mode parameter "
+							"data\n");
 					goto defaults;
 				} else {
 					modepage = page_code;
@@ -2434,14 +2436,15 @@ sd_read_cache_type(struct scsi_disk *sdkp, unsigned char *buffer)
 				else if (!spf && len - offset > 1)
 					offset += 2 + buffer[offset+1];
 				else {
-					sd_printk(KERN_ERR, sdkp, "Incomplete "
-						  "mode parameter data\n");
+					sd_first_printk(KERN_ERR, sdkp,
+							"Incomplete mode "
+							"parameter data\n");
 					goto defaults;
 				}
 			}
 		}
 
-		sd_printk(KERN_ERR, sdkp, "No Caching mode page found\n");
+		sd_first_printk(KERN_ERR, sdkp, "No Caching mode page found\n");
 		goto defaults;
 
 	Page_found:
@@ -2455,7 +2458,7 @@ sd_read_cache_type(struct scsi_disk *sdkp, unsigned char *buffer)
 
 		sdkp->DPOFUA = (data.device_specific & 0x10) != 0;
 		if (sdkp->DPOFUA && !sdkp->device->use_10_for_rw) {
-			sd_printk(KERN_NOTICE, sdkp,
+			sd_first_printk(KERN_NOTICE, sdkp,
 				  "Uses READ/WRITE(6), disabling FUA\n");
 			sdkp->DPOFUA = 0;
 		}
@@ -2477,16 +2480,19 @@ bad_sense:
 	    sshdr.sense_key == ILLEGAL_REQUEST &&
 	    sshdr.asc == 0x24 && sshdr.ascq == 0x0)
 		/* Invalid field in CDB */
-		sd_printk(KERN_NOTICE, sdkp, "Cache data unavailable\n");
+		sd_first_printk(KERN_NOTICE, sdkp, "Cache data unavailable\n");
 	else
-		sd_printk(KERN_ERR, sdkp, "Asking for cache data failed\n");
+		sd_first_printk(KERN_ERR, sdkp,
+				"Asking for cache data failed\n");
 
 defaults:
 	if (sdp->wce_default_on) {
-		sd_printk(KERN_NOTICE, sdkp, "Assuming drive cache: write back\n");
+		sd_first_printk(KERN_NOTICE, sdkp,
+				"Assuming drive cache: write back\n");
 		sdkp->WCE = 1;
 	} else {
-		sd_printk(KERN_ERR, sdkp, "Assuming drive cache: write through\n");
+		sd_first_printk(KERN_ERR, sdkp,
+				"Assuming drive cache: write through\n");
 		sdkp->WCE = 0;
 	}
 	sdkp->RCD = 0;
@@ -2515,7 +2521,7 @@ static void sd_read_app_tag_own(struct scsi_disk *sdkp, unsigned char *buffer)
 
 	if (!scsi_status_is_good(res) || !data.header_length ||
 	    data.length < 6) {
-		sd_printk(KERN_WARNING, sdkp,
+		sd_first_printk(KERN_WARNING, sdkp,
 			  "getting Control mode page failed, assume no ATO\n");
 
 		if (scsi_sense_valid(&sshdr))
@@ -2527,7 +2533,7 @@ static void sd_read_app_tag_own(struct scsi_disk *sdkp, unsigned char *buffer)
 	offset = data.header_length + data.block_descriptor_length;
 
 	if ((buffer[offset] & 0x3f) != 0x0a) {
-		sd_printk(KERN_ERR, sdkp, "ATO Got wrong page\n");
+		sd_first_printk(KERN_ERR, sdkp, "ATO Got wrong page\n");
 		return;
 	}
 
diff --git a/drivers/scsi/sd.h b/drivers/scsi/sd.h
index 26895ff247c5..59956e9a5b80 100644
--- a/drivers/scsi/sd.h
+++ b/drivers/scsi/sd.h
@@ -104,6 +104,11 @@ static inline struct scsi_disk *scsi_disk(struct gendisk *disk)
 		    (sdsk)->disk->disk_name, ##a) :			\
 	sdev_printk(prefix, (sdsk)->device, fmt, ##a)
 
+#define sd_first_printk(prefix,sdsk, fmt, a...)				\
+	do {								\
+	if ((sdkp)->first_scan) sd_printk(prefix, sdsk, fmt, ##a);	\
+	} while (0)
+
 static inline int scsi_medium_access_command(struct scsi_cmnd *scmd)
 {
 	switch (scmd->cmnd[0]) {

Re: Bug#733565: SIX messages per on boot console should be TWO

[jidanni]

>>>>> "MKP" == Martin K Petersen <martin.petersen@oracle.com> writes:
MKP> [SCSI] sd: Quiesce mode sense error messages
Thanks!