PROBLEM: udf mount takes forever to fail + proposed solution

PROBLEM: udf mount takes forever to fail + proposed solution

[Péter András Felvégi]

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

Hello,

recently I made the mistake trying to mount an unformatted ssd
partition. The mount command 'hang', was unable to kill it. Top showed
the process is in the uninterruptible D state. However, iotop showed
slight activity, about 4M/s read from the disk that noone else used.
This was 100% reproducible. sync froze, too, if was given out after
the mount cmd. When trying to shut down the machine, it didn't stop,
just waited for something to happen.

I narrowed down the problem to the UDF filesystem driver. In
fs/udf/super.c, udf_check_vsd() reads the sectors in a for loop, with
the following exit conditions:
- NSR02 or NSR03 descriptor is found
- the read fails
- vsd->stdIdent[0] == 0

Browsed through the UDF 2.6 spec, ECMA 167 and 119. As I understand,
the descriptors should start at offset 32768, forming a contiguous
sequence. In ECMA 167 it is stated that the sequence is terminated by
an invalid descriptor: unrecorded, or blank (all zeros). However, this
presupposes that the filesystem is UDF.

Since the ssd partition was not formatted, it contained only 0xff
bytes, thus none of the exit conditions were met, and the function
read through the whole, in two passes. The runtime was pathetic, it
took the mount 350 minutes to fail. I have no clue why this was so
slow, reading through the partition with dd gives 482 secs for the
220G, ~450M/s. Setting the blocksize to 512 or 2048 didn't make much
of a difference.

I peppered the code with some messages to see what happens:
# time mount -t udf /dev/sdb3 /media/floppy
UDF-fs: check_vsd: sectorsize=2048
UDF-fs: check_vsd: sector offs=32768, s_blocksize=512, s_blocksize_bits=9
UDF-fs: read 107989660 sectors of total size 55290705920 bytes
UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
UDF-fs: Rescanning with blocksize 2048
UDF-fs: check_vsd: sectorsize=2048
UDF-fs: check_vsd: sector offs=32768, s_blocksize=2048, s_blocksize_bits=11
UDF-fs: read 107989660 sectors of total size 221162823680 bytes
UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
UDF-fs: warning (device sdb3): udf_fill_super: No partition found (1)
mount: wrong fs type, bad option, bad superblock on /dev/sdb3,
       missing codepage or helper program, or other error
       In some cases useful info is found in syslog - try
       dmesg | tail  or so
real    352m4.740s
user    0m0.000s
sys     27m23.560s

Tried to mount other partitions, too, formatted to ext3, ext4, btrfs
and ntfs. The mount failed with those sooner, accidentally just
because there were some blocks near to the beginning with a zero byte
just at the right place.

Then I prepared an 'all 0xff' 4G image, and burnt it to a DVD. The
mount failed, but took only 25 minutes. 'Only', compared to the case
with the ssd. This truely doesn't reflect the throughput of the
devices, hopefully someone with more experience will have a clue.

The proposed solution changes the for() loop exit condition so that
not a zero byte but an invalid descriptor id is checked. Since all
current ids are 0-9A-Z, I think it's plausible to expect future ids
will have the same form. If not, the code could be changed later,
anyway.

Mounting the invalid ssd partition with the patch in debug mode looks like this:
# time mount -t udf /dev/sdb3 /media/floppy
UDF-fs: udf_is_vsd_id_valid: at offset 0x00008000 vsd.stdIdent[] = {
ff ff ff ff ff } : invalid
UDF-fs: warning (device sdb3): udf_load_vrs: No anchor found
UDF-fs: Rescanning with blocksize 2048
UDF-fs: udf_is_vsd_id_valid: at offset 0x00008000 vsd.stdIdent[] = {
ff ff ff ff ff } : invalid
UDF-fs: warning (device sdb3): udf_load_vrs: No anchor found
UDF-fs: warning (device sdb3): udf_fill_super: No partition found (1)
mount: wrong fs type, bad option, bad superblock on /dev/sdb3,
       missing codepage or helper program, or other error
       In some cases useful info is found in syslog - try
       dmesg | tail  or so
real    0m0.009s
user    0m0.000s
sys     0m0.000s

And with a valid UDF fs:
# time mount -t udf /dev/sr1 /media/floppy
mount: block device /dev/sr1 is write-protected, mounting read-only
UDF-fs: udf_is_vsd_id_valid: at offset 0x00008000 vsd.stdIdent[] = {
43 44 30 30 31 } : valid (CD001)
UDF-fs: udf_is_vsd_id_valid: at offset 0x00008800 vsd.stdIdent[] = {
43 44 30 30 31 } : valid (CD001)
UDF-fs: udf_is_vsd_id_valid: at offset 0x00009000 vsd.stdIdent[] = {
42 45 41 30 31 } : valid (BEA01)
UDF-fs: udf_is_vsd_id_valid: at offset 0x00009800 vsd.stdIdent[] = {
4e 53 52 30 32 } : valid (NSR02)
UDF-fs: Partition marked readonly; forcing readonly mount
real    0m0.290s
user    0m0.000s
sys     0m0.000s

Please comment on the attached patch and merge it if acceptable. It
was made against 0bfd8ff (v3.9.4), but applied successfully to
v3.12-rc3, too.

Kind regards, Peter

[-- Attachment #2: super.patch --]
[-- Type: application/octet-stream, Size: 1989 bytes --]

diff --git a/fs/udf/super.c b/fs/udf/super.c
index 9ac4057..b9306f8 100644
--- a/fs/udf/super.c
+++ b/fs/udf/super.c
@@ -667,6 +667,40 @@ out_unlock:
 	return error;
 }
 
+static int udf_is_vsd_id_valid(loff_t off, const struct volStructDesc* vsd)
+{
+	/* Suppose all valid identifiers are 0-9A-Z */
+	int v = 1;
+	int i;
+	for (i = 0; i < sizeof(vsd->stdIdent); ++i) {
+		int c = vsd->stdIdent[i];
+		/* isalnum(c) gives false positives, eg for 0xff */
+		if ((c < '0' || c > '9') && (c < 'A' || c > 'Z')) {
+			v = 0;
+			break;
+		}
+	}
+#ifdef UDFFS_DEBUG
+	{
+		char hex[sizeof(vsd->stdIdent) * 3 + 1] = { 0 };
+		char chr[sizeof(vsd->stdIdent) + 1 ] = { 0 };
+		char* hp = hex;
+		char* he = hex + sizeof(hex);
+		char* cp = chr;
+		char* ce = chr + sizeof(chr);
+		for (i = 0; i < sizeof(vsd->stdIdent); ++i) {
+			snprintf(hp, he - hp, "%02x ", vsd->stdIdent[i]);
+			hp += 3;
+			snprintf(cp, ce - cp, "%c", vsd->stdIdent[i]);
+			++cp;
+		}
+		pr_notice("%s: at offset 0x%08llx vsd.stdIdent[] = { %s} : %s%s%s%s\n", __func__, off, hex,
+			  v ? "valid" : "invalid", v ? " (" : "", v ? chr : "", v ? ")" : "");
+	}
+#endif
+	return v;
+}
+
 /* Check Volume Structure Descriptors (ECMA 167 2/9.1) */
 /* We also check any "CD-ROM Volume Descriptor Set" (ECMA 167 2/8.3.1) */
 static loff_t udf_check_vsd(struct super_block *sb)
@@ -701,7 +735,7 @@ static loff_t udf_check_vsd(struct super_block *sb)
 		vsd = (struct volStructDesc *)(bh->b_data +
 					      (sector & (sb->s_blocksize - 1)));
 
-		if (vsd->stdIdent[0] == 0) {
+		if (!udf_is_vsd_id_valid(sector, vsd)) {
 			brelse(bh);
 			break;
 		} else if (!strncmp(vsd->stdIdent, VSD_STD_ID_CD001,
@@ -1239,6 +1273,9 @@ static int udf_load_partdesc(struct super_block *sb, sector_t block)
 	 * PHYSICAL partitions are already set up
 	 */
 	type1_idx = i;
+#ifdef UDFFS_DEBUG
+	map = NULL; /* supress 'maybe used uninitialized' warning */
+#endif
 	for (i = 0; i < sbi->s_partitions; i++) {
 		map = &sbi->s_partmaps[i];
 

Re: PROBLEM: udf mount takes forever to fail + proposed solution

[Jan Kara]

  Hello,

On Thu 10-10-13 23:23:11, Péter András Felvégi wrote:
> recently I made the mistake trying to mount an unformatted ssd
> partition. The mount command 'hang', was unable to kill it. Top showed
> the process is in the uninterruptible D state. However, iotop showed
> slight activity, about 4M/s read from the disk that noone else used.
> This was 100% reproducible. sync froze, too, if was given out after
> the mount cmd. When trying to shut down the machine, it didn't stop,
> just waited for something to happen.
> 
> I narrowed down the problem to the UDF filesystem driver. In
> fs/udf/super.c, udf_check_vsd() reads the sectors in a for loop, with
> the following exit conditions:
> - NSR02 or NSR03 descriptor is found
> - the read fails
> - vsd->stdIdent[0] == 0
> 
> Browsed through the UDF 2.6 spec, ECMA 167 and 119. As I understand,
> the descriptors should start at offset 32768, forming a contiguous
> sequence. In ECMA 167 it is stated that the sequence is terminated by
> an invalid descriptor: unrecorded, or blank (all zeros). However, this
> presupposes that the filesystem is UDF.
> 
> Since the ssd partition was not formatted, it contained only 0xff
> bytes, thus none of the exit conditions were met, and the function
> read through the whole, in two passes. The runtime was pathetic, it
> took the mount 350 minutes to fail. I have no clue why this was so
> slow, reading through the partition with dd gives 482 secs for the
> 220G, ~450M/s. Setting the blocksize to 512 or 2048 didn't make much
> of a difference.
> 
> I peppered the code with some messages to see what happens:
> # time mount -t udf /dev/sdb3 /media/floppy
> UDF-fs: check_vsd: sectorsize=2048
> UDF-fs: check_vsd: sector offs=32768, s_blocksize=512, s_blocksize_bits=9
> UDF-fs: read 107989660 sectors of total size 55290705920 bytes
> UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
> UDF-fs: Rescanning with blocksize 2048
> UDF-fs: check_vsd: sectorsize=2048
> UDF-fs: check_vsd: sector offs=32768, s_blocksize=2048, s_blocksize_bits=11
> UDF-fs: read 107989660 sectors of total size 221162823680 bytes
> UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
> UDF-fs: warning (device sdb3): udf_fill_super: No partition found (1)
> mount: wrong fs type, bad option, bad superblock on /dev/sdb3,
>        missing codepage or helper program, or other error
>        In some cases useful info is found in syslog - try
>        dmesg | tail  or so
> real    352m4.740s
> user    0m0.000s
> sys     27m23.560s
> 
> Tried to mount other partitions, too, formatted to ext3, ext4, btrfs
> and ntfs. The mount failed with those sooner, accidentally just
> because there were some blocks near to the beginning with a zero byte
> just at the right place.
> 
> Then I prepared an 'all 0xff' 4G image, and burnt it to a DVD. The
> mount failed, but took only 25 minutes. 'Only', compared to the case
> with the ssd. This truely doesn't reflect the throughput of the
> devices, hopefully someone with more experience will have a clue.
  Thanks for the report and detailed analysis. Frankly, instead of your
function checking the identifier, I'd rather follow the standard in detail
and add handling (meaning ignore) of the remaining specified descriptors
(CDW02, BOOT2) and bail out if anything else is found. If someone complains
because some broken medium stops mounting, we can try something more
elaborate but for now I'd go with the simple solution.

Also please read Documentation/SubmittingPatches - your patch was missing a
changelog entry (you can basically take your somewhat shortened email for
that) and a Signed-off-by line. Thanks!

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

Re: PROBLEM: udf mount takes forever to fail + proposed solution

[Péter András Felvégi]

OK, I'll prepare a new patch with explicit ID checks (BEA01, BOOT2,
CDROM, CD001, CDW02, NSR02, NSR03, TEA01, that's all I think) and the
needed changelog in a few days. Do you think that a hard upper limit
on the sector offset is desirable? The ISO9660 driver looks for the
first 100 sectors, but I didn't find anything in the specs suggesting
a max length for the udf volume recognition area.

Regards, Peter


On 11 October 2013 17:18, Jan Kara <jack@suse.cz> wrote:
>   Hello,
>
> On Thu 10-10-13 23:23:11, Péter András Felvégi wrote:
>> recently I made the mistake trying to mount an unformatted ssd
>> partition. The mount command 'hang', was unable to kill it. Top showed
>> the process is in the uninterruptible D state. However, iotop showed
>> slight activity, about 4M/s read from the disk that noone else used.
>> This was 100% reproducible. sync froze, too, if was given out after
>> the mount cmd. When trying to shut down the machine, it didn't stop,
>> just waited for something to happen.
>>
>> I narrowed down the problem to the UDF filesystem driver. In
>> fs/udf/super.c, udf_check_vsd() reads the sectors in a for loop, with
>> the following exit conditions:
>> - NSR02 or NSR03 descriptor is found
>> - the read fails
>> - vsd->stdIdent[0] == 0
>>
>> Browsed through the UDF 2.6 spec, ECMA 167 and 119. As I understand,
>> the descriptors should start at offset 32768, forming a contiguous
>> sequence. In ECMA 167 it is stated that the sequence is terminated by
>> an invalid descriptor: unrecorded, or blank (all zeros). However, this
>> presupposes that the filesystem is UDF.
>>
>> Since the ssd partition was not formatted, it contained only 0xff
>> bytes, thus none of the exit conditions were met, and the function
>> read through the whole, in two passes. The runtime was pathetic, it
>> took the mount 350 minutes to fail. I have no clue why this was so
>> slow, reading through the partition with dd gives 482 secs for the
>> 220G, ~450M/s. Setting the blocksize to 512 or 2048 didn't make much
>> of a difference.
>>
>> I peppered the code with some messages to see what happens:
>> # time mount -t udf /dev/sdb3 /media/floppy
>> UDF-fs: check_vsd: sectorsize=2048
>> UDF-fs: check_vsd: sector offs=32768, s_blocksize=512, s_blocksize_bits=9
>> UDF-fs: read 107989660 sectors of total size 55290705920 bytes
>> UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
>> UDF-fs: Rescanning with blocksize 2048
>> UDF-fs: check_vsd: sectorsize=2048
>> UDF-fs: check_vsd: sector offs=32768, s_blocksize=2048, s_blocksize_bits=11
>> UDF-fs: read 107989660 sectors of total size 221162823680 bytes
>> UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
>> UDF-fs: warning (device sdb3): udf_fill_super: No partition found (1)
>> mount: wrong fs type, bad option, bad superblock on /dev/sdb3,
>>        missing codepage or helper program, or other error
>>        In some cases useful info is found in syslog - try
>>        dmesg | tail  or so
>> real    352m4.740s
>> user    0m0.000s
>> sys     27m23.560s
>>
>> Tried to mount other partitions, too, formatted to ext3, ext4, btrfs
>> and ntfs. The mount failed with those sooner, accidentally just
>> because there were some blocks near to the beginning with a zero byte
>> just at the right place.
>>
>> Then I prepared an 'all 0xff' 4G image, and burnt it to a DVD. The
>> mount failed, but took only 25 minutes. 'Only', compared to the case
>> with the ssd. This truely doesn't reflect the throughput of the
>> devices, hopefully someone with more experience will have a clue.
>   Thanks for the report and detailed analysis. Frankly, instead of your
> function checking the identifier, I'd rather follow the standard in detail
> and add handling (meaning ignore) of the remaining specified descriptors
> (CDW02, BOOT2) and bail out if anything else is found. If someone complains
> because some broken medium stops mounting, we can try something more
> elaborate but for now I'd go with the simple solution.
>
> Also please read Documentation/SubmittingPatches - your patch was missing a
> changelog entry (you can basically take your somewhat shortened email for
> that) and a Signed-off-by line. Thanks!
>
>                                                                 Honza
> --
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR

Re: PROBLEM: udf mount takes forever to fail + proposed solution

[Jan Kara]

On Fri 11-10-13 23:46:37, Péter András Felvégi wrote:
> OK, I'll prepare a new patch with explicit ID checks (BEA01, BOOT2,
> CDROM, CD001, CDW02, NSR02, NSR03, TEA01, that's all I think) and the
> needed changelog in a few days. Do you think that a hard upper limit
> on the sector offset is desirable? The ISO9660 driver looks for the
> first 100 sectors, but I didn't find anything in the specs suggesting
> a max length for the udf volume recognition area.
  Certainly a bound like 100 sectors would likely be OK as well. But as you
already said, there isn't any such a limit in the spec so we can only guess
which limit to pick... If using fixed strings won't work out, using a limit
like 100 sectors would probably be the next best solution for me.

								Honza

> On 11 October 2013 17:18, Jan Kara <jack@suse.cz> wrote:
> >   Hello,
> >
> > On Thu 10-10-13 23:23:11, Péter András Felvégi wrote:
> >> recently I made the mistake trying to mount an unformatted ssd
> >> partition. The mount command 'hang', was unable to kill it. Top showed
> >> the process is in the uninterruptible D state. However, iotop showed
> >> slight activity, about 4M/s read from the disk that noone else used.
> >> This was 100% reproducible. sync froze, too, if was given out after
> >> the mount cmd. When trying to shut down the machine, it didn't stop,
> >> just waited for something to happen.
> >>
> >> I narrowed down the problem to the UDF filesystem driver. In
> >> fs/udf/super.c, udf_check_vsd() reads the sectors in a for loop, with
> >> the following exit conditions:
> >> - NSR02 or NSR03 descriptor is found
> >> - the read fails
> >> - vsd->stdIdent[0] == 0
> >>
> >> Browsed through the UDF 2.6 spec, ECMA 167 and 119. As I understand,
> >> the descriptors should start at offset 32768, forming a contiguous
> >> sequence. In ECMA 167 it is stated that the sequence is terminated by
> >> an invalid descriptor: unrecorded, or blank (all zeros). However, this
> >> presupposes that the filesystem is UDF.
> >>
> >> Since the ssd partition was not formatted, it contained only 0xff
> >> bytes, thus none of the exit conditions were met, and the function
> >> read through the whole, in two passes. The runtime was pathetic, it
> >> took the mount 350 minutes to fail. I have no clue why this was so
> >> slow, reading through the partition with dd gives 482 secs for the
> >> 220G, ~450M/s. Setting the blocksize to 512 or 2048 didn't make much
> >> of a difference.
> >>
> >> I peppered the code with some messages to see what happens:
> >> # time mount -t udf /dev/sdb3 /media/floppy
> >> UDF-fs: check_vsd: sectorsize=2048
> >> UDF-fs: check_vsd: sector offs=32768, s_blocksize=512, s_blocksize_bits=9
> >> UDF-fs: read 107989660 sectors of total size 55290705920 bytes
> >> UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
> >> UDF-fs: Rescanning with blocksize 2048
> >> UDF-fs: check_vsd: sectorsize=2048
> >> UDF-fs: check_vsd: sector offs=32768, s_blocksize=2048, s_blocksize_bits=11
> >> UDF-fs: read 107989660 sectors of total size 221162823680 bytes
> >> UDF-fs: warning (device sdb3): udf_load_vrs: No VRS found
> >> UDF-fs: warning (device sdb3): udf_fill_super: No partition found (1)
> >> mount: wrong fs type, bad option, bad superblock on /dev/sdb3,
> >>        missing codepage or helper program, or other error
> >>        In some cases useful info is found in syslog - try
> >>        dmesg | tail  or so
> >> real    352m4.740s
> >> user    0m0.000s
> >> sys     27m23.560s
> >>
> >> Tried to mount other partitions, too, formatted to ext3, ext4, btrfs
> >> and ntfs. The mount failed with those sooner, accidentally just
> >> because there were some blocks near to the beginning with a zero byte
> >> just at the right place.
> >>
> >> Then I prepared an 'all 0xff' 4G image, and burnt it to a DVD. The
> >> mount failed, but took only 25 minutes. 'Only', compared to the case
> >> with the ssd. This truely doesn't reflect the throughput of the
> >> devices, hopefully someone with more experience will have a clue.
> >   Thanks for the report and detailed analysis. Frankly, instead of your
> > function checking the identifier, I'd rather follow the standard in detail
> > and add handling (meaning ignore) of the remaining specified descriptors
> > (CDW02, BOOT2) and bail out if anything else is found. If someone complains
> > because some broken medium stops mounting, we can try something more
> > elaborate but for now I'd go with the simple solution.
> >
> > Also please read Documentation/SubmittingPatches - your patch was missing a
> > changelog entry (you can basically take your somewhat shortened email for
> > that) and a Signed-off-by line. Thanks!
> >
> >                                                                 Honza
> > --
> > Jan Kara <jack@suse.cz>
> > SUSE Labs, CR
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR