make-edge-iso.sh fails on focal/ppc64el images

[Paride Legovini]

Since 2021-02-01 make-edge-iso.sh stopped working on the focal-live-server-ppc64el daily images, failing with error:

----------------------------------

+ xorriso -as mkisofs -V 'Ubuntu-Server 20.04.2 LTS ppc64' --modification-date=2021020117592100 -partition_cyl_align off -partition_offset 0 -append_partition 4 0x8 --interval:local_fs:1718121313d-3352666579d::/var/cache/utah/iso/focal-live-server-ppc64el.iso -apm-block-size 512 -G --interval:local_fs:0s-15s:zero_mbrpt,zero_apm:/var/cache/utah/iso/focal-live-server-ppc64el.iso -iso_mbr_part_type 0x96 -no-pad -o /jenkins/servers/platformqa/workspace/ubuntu-focal-live-server-ppc64el-smoke-edge/edge-focal-live-server-ppc64el.iso -V 'Ubuntu custom' new_iso
xorriso 1.4.8 : RockRidge filesystem manipulator, libburnia project.

Drive current: -outdev 'stdio:/jenkins/servers/platformqa/workspace/ubuntu-focal-live-server-ppc64el-smoke-edge/edge-focal-live-server-ppc64el.iso'
Media current: stdio file, overwriteable
Media status : is blank
Media summary: 0 sessions, 0 data blocks, 0 data, 244g free
xorriso : WARNING : -volid text problematic as automatic mount point name
xorriso : WARNING : -volid text does not comply to ISO 9660 / ECMA 119 rules
xorriso : WARNING : -volid text problematic as automatic mount point name
xorriso : WARNING : -volid text does not comply to ISO 9660 / ECMA 119 rules
Added to ISO image: directory '/'='/tmp/tmp.n8TB7KD0Wm/new_iso'
xorriso : UPDATE : 141 files added in 1 seconds
xorriso : UPDATE : 141 files added in 1 seconds
xorriso : NOTE : Copying to System Area: 32768 bytes from file '--interval:local_fs:0s-15s:zero_mbrpt,zero_apm:/var/cache/utah/iso/focal-live-server-ppc64el.iso'
libisofs: NOTE : Automatically adjusted MBR geometry to 1017/81/32
xorriso : FAILURE : Image size 409295092s exceeds free space on media 127778488s
libisofs: MISHAP : Image write cancelled
xorriso : NOTE : -return_with SORRY 32 triggered by problem severity FAILURE

----------------------------------

This happens with xorriso from Bionic and Focal. I researched the error a bit and normally it seems associated with not enough disk space in the target directory, but this is not the case of the system where I'm hitting this issue, as I have 243G free in the target partition. I also tried with a different target partition with 142G free, just in case, same failure.

I tried dropping the `-o` option entirely, which should make xorriso output to stdout, but it still failed with that error.

Are we perhaps hitting an upper limit of the generated ISO image itself? We're speaking of about 1.3GB so I'd be surprised (it's way less than a single layer DVD), but on 2021-02-01 the daily ISO images started including the HWE kernel, and their size increased quite a bit.

[Michael Hudson-Doyle (mwhudson)]

Assuming the s in 409295092s means 512 byte sectors, then that's something like 195 gigabytes and 127778488s is around 60 gigabytes. I don't know why xorriso would think that the ISO needs that much space...

Nothing relevant changed in subiquity on 2021-02-01 that I can see, so I think it must be the HWE kernel. Do you still have logs from a successful run before that? Maybe -report_el_torito as_mkisofs is going crazy.

[Paride Legovini (paride)]

I searched for possibly relevant upstream xorriso bugs but only found old issues which are certainly fixed in all the supported Ubuntu releases. I wonder if this is arch dependent for some odd reason.

I'm attaching the log of the latest successful run, which ran using the ISO with the following media info:

Ubuntu-Server 20.04.2 LTS "Focal Fossa" - Release ppc64el (20210129)

Xorriso behaved well in this case:

+ xorriso -as mkisofs -V 'Ubuntu-Server 20.04.2 LTS ppc64' --modification-date=2021012910021700 -partition_cyl_align off -partition_offset 0 -apm-block-size 512 -G --interval:local_fs:0s-15s:zero_mbrpt,zero_apm:/var/cache/utah/iso/focal-live-server-ppc64el.iso -iso_mbr_part_type 0x96 -o /jenkins/servers/platformqa/workspace/ubuntu-focal-live-server-ppc64el-smoke-edge/edge-focal-live-server-ppc64el.iso -V 'Ubuntu custom' new_iso
xorriso 1.4.8 : RockRidge filesystem manipulator, libburnia project.

Drive current: -outdev 'stdio:/jenkins/servers/platformqa/workspace/ubuntu-focal-live-server-ppc64el-smoke-edge/edge-focal-live-server-ppc64el.iso'
Media current: stdio file, overwriteable
Media status : is blank
Media summary: 0 sessions, 0 data blocks, 0 data, 241g free
xorriso : WARNING : -volid text problematic as automatic mount point name
xorriso : WARNING : -volid text does not comply to ISO 9660 / ECMA 119 rules
xorriso : WARNING : -volid text problematic as automatic mount point name
xorriso : WARNING : -volid text does not comply to ISO 9660 / ECMA 119 rules
Added to ISO image: directory '/'='/tmp/tmp.PYltA0oLMJ/new_iso'
xorriso : UPDATE : 130 files added in 1 seconds
xorriso : UPDATE : 130 files added in 1 seconds
xorriso : NOTE : Copying to System Area: 32768 bytes from file '--interval:local_fs:0s-15s:zero_mbrpt,zero_apm:/var/cache/utah/iso/focal-live-server-ppc64el.iso'
libisofs: NOTE : Automatically adjusted MBR geometry to 1012/77/32
xorriso : UPDATE : 8.98% done
xorriso : UPDATE : 54.53% done
ISO image produced: 623348 sectors
Written to medium : 623348 sectors at LBA 0
Writing to 'stdio:/jenkins/servers/platformqa/workspace/ubuntu-focal-live-server-ppc64el-smoke-edge/edge-focal-live-server-ppc64el.iso' completed successfully.

[Michael Hudson-Doyle (mwhudson)]

Well the command lines are quite different: the failing one has these extra arguments: -append_partition 4 0x8 --interval:local_fs:1718121313d-3352666579d::/var/cache/utah/iso/focal-live-server-ppc64el.iso -no-pad.

I've now found the bit of xorriso documentation which explains the suffixes: s == 2048 bytes and d == 512 bytes. So 409295092s is about 780 gigabytes and 243. And the arguments to that --interval switch come out suspiciously close to the amount xorriso is complaining about:

>>> 409295092 * 2048
838236348416
>>> (3352666579-1718121313) * 512
836887176192
>>> (3352666579-1718121313) * 512 - 409295092 * 2048
-1349172224

So my vote is for "-report_el_torito as_mkisofs going crazy".

[Paride Legovini (paride)]

Well, those tens-of-gigabytes image sizes are definitely not normal. I tried to make xorriso output to stdout to make it skip the free space on target partition check, but it failed in the same way.

I added a libisoburn (= xorriso) task to this bug and subscribed Thomas Schmitt, in case he wants to chime in :)

[Thomas Schmitt (scdbackup)]

Hi,

> xorriso : FAILURE : Image size 409295092s exceeds free space on media 127778488s

So you already found out that the ISO would contain
  409295092s = 409295092 * 2048 bytes ~= 781 GiB

and spotted this option with its arguments:

> -append_partition 4 0x8 --interval:local_fs:1718121313d-3352666579d::/var/cache/utah/iso/focal-live-server-ppc64el.iso

"d" is index 512 (disk block). So this tells xorriso to cut
  (3352666580 - 1718121313) * 512 bytes ~= 780 GiB
out of file
  /var/cache/utah/iso/focal-live-server-ppc64el.iso

I just tried a mini version of the command with a file that is much too
small for that interval.
xorriso is credulent enough to virtually do this by "reading" and
writing all 0s.
(I need to think whether there was a reason to let it read over the end
of an input file. Being too picky would spoil a run. But being that
generous seems wrong.)

Nevertheless, the problem is in the decision of the controlling software
to demand an interval of 780 GiB out of a file which then should have
at least ~ 1.6 GiB.
The numbers without suffix would mean to cut 1.6 GiB out of 3.2 GiB.
A bit more plausible for a DVD sized image. But why cut out half of that
image and declare it an AIX partition (by 0x8) ?

Is there a public place where i can see the script "make-edge-iso.sh" ?

Have a nice day :)

Thomas

[Thomas Schmitt (scdbackup)]

I wrote:
> "d" is index 512 (disk block).

That was meant as

  "d" is indeed 512 (disk block).

[Paride Legovini (paride)]

Hi,

The interesting bits of the script are at [1], however more concise steps to reproduce are:

1. download [2]
2. xorriso -indev focal-live-server-ppc64el.iso -report_el_torito as_mkisofs

This generates a list of "as mkisofs" options containing the '--interval:local_fs:1718121313d-3352666579d' one.

Thanks!

[1] https://github.com/CanonicalLtd/subiquity/blob/main/scripts/inject-subiquity-snap.sh#L194
[2] https://cdimage.ubuntu.com/ubuntu-server/focal/daily-live/pending/focal-live-server-ppc64el.iso

[Thomas Schmitt (scdbackup)]

Hi,

> 1. download [2]
> 2. xorriso -indev focal-live-server-ppc64el.iso -report_el_torito as_mkisofs

The adventure moves to the question how this ISO got its partition table.

  $ xorriso -indev focal-live-server-ppc64el.iso -report_system_area plain
  ...
  ISO image size/512 : 2440600
  ...
  MBR partition table: N Status Type Start Blocks
  MBR partition : 1 0x80 0x96 0 2440000
  MBR partition : 4 0x00 0x08 1718121313 1634545267
  ...

Partition editors see it even worse

  $ /sbin/fdisk -l focal-live-server-ppc64el.iso
  ...
  Device Boot Start End Sectors Size Id Type
  focal-live-server-ppc64el.iso1 * 0 2439999 2440000 1.2G 96 unknown
  focal-live-server-ppc64el.iso2 ? 31335 31335 0 0B 74 unknown
  focal-live-server-ppc64el.iso3 33554432 33554432 0 0B c9 unknown
  focal-live-server-ppc64el.iso4 1718121313 3352666579 1634545267 779.4G 8 AIX

Inquiring the Primary Volume Descriptor:

  $ xorriso -indev focal-live-server-ppc64el.iso -pvd_info
  ...
  App Id : GENISOIMAGE ISO 9660/HFS FILESYSTEM CREATOR (C) 1993 E.YOUNGDALE (C) 1997-2006 J.PEARSON/J.SCHILLING (C) 2006-2007 CDRKIT TEAM
  ...

Partition type 0x96 means CHRP. My cheat sheet says:

  CHRP is marked by an MBR partition entry of type 0x96 spanning the whole
  ISO 9660 image.

It seems that i interpreted this in the recognition code for CHRP as
"only one partition is allowed and that must be of type 0x96".
Possibly this is too narrow.

After overwriting the debris in the partition table by

  cp focal-live-server-ppc64el.iso test.iso
  dd if=/dev/zero conv=notrunc of=test.iso bs=1 count=48 seek=462

i get

  $ /sbin/fdisk -l test.iso
  ...
  Device Boot Start End Sectors Size Id Type
  test.iso1 * 0 2439999 2440000 1.2G 96 unknown
  ...

So xorriso's proposal mutates from copying the debris as appended partition
to producing a CHRP ISO:

  $ xorriso -indev test.iso -report_el_torito as_mkisofs
  ...
  -V 'Ubuntu-Server 20.04.2 LTS ppc64'
  --modification-date='2021020910083100'
  -chrp-boot-part
  -partition_cyl_align off
  -partition_offset 0
  --mbr-force-bootable
  -apm-block-size 512
  -G --interval:local_fs:0s-15s:zero_mbrpt,zero_apm:'test.iso'
  -iso_mbr_part_type 0x96
  ...

(-iso_mbr_part_type 0x96 is already impled by -chrp-boot-part.)

But this cannot replay completely what the focal-live-server-ppc64el.iso
image contains:

  $ xorriso -indev test.iso -report_system_area plain
  ...
  System area summary: MBR CHRP cyl-align-off APM
  ISO image size/512 : 2440600
  Partition offset : 0
  MBR heads per cyl : 0
  MBR secs per head : 0
  MBR partition table: N Status Type Start Blocks
  MBR partition : 1 0x80 0x96 0 2440000
  APM : N Info
  APM block size : 512
  APM gap fillers : 0
  APM partition name : 1 Ubuntu-Server 20.04.2 LTS ppc64
  APM partition type : 1 Apple_HFS
  APM start and size : 1 16 2439984

So here we obviously have an ISO/HFS hybrid, which explains why this ISO
was not ma...

[Thomas Schmitt (scdbackup)]

Hi,

i forgot to propose that make-edge-iso.sh should look in stderr of the
"xorriso -report_el_torito as_mkisofs" run for this message:

  xorriso : SORRY : Cannot make proposal to produce APM of loaded image

and/or that it should check for the exit value of the xorriso run, which
in this case will be 32 rather than 0.
(That exit value is a consequence of the xorriso default setting
   -return_with SORRY 32
Which means not to abort on a SORRY message, but to indicate a problem
by the return value of the program.)

Have a nice day :)

Thomas

[Michael Hudson-Doyle (mwhudson)]

The construction of the iso is buried in https://people.canonical.com/~ubuntu-archive/cd-build-logs/ubuntu-server/focal/daily-live-20210209.log, for ppc64el it seems to be:

/usr/bin/mkisofs -r -V Ubuntu-Server\ 20.04.2\ LTS\ ppc64 -o /srv/cdimage.ubuntu.com/scratch/ubuntu-server/focal/daily-live/debian-cd/ppc64el/focal-live-server-ppc64el.raw --netatalk -hfs -probe -map /srv/cdimage.ubuntu.com/debian-cd/data/hfs.map -chrp-boot -iso-level 4 -part -no-desktop -hfs-bless CD1/install -hfs-volid Ubuntu-Server_PPC64EL_focal -sort /srv/cdimage.ubuntu.com/scratch/ubuntu-server/focal/daily-live/tmp/focal-ppc64el/1.weights CD1

I don't know why we use mkisofs rather than xorriso for ppc64el. Maybe we should switch.

I proposed https://github.com/CanonicalLtd/subiquity/pull/892 to fail if -report_el_torito fails.

[Thomas Schmitt (scdbackup)]

Hi,

> /usr/bin/mkisofs -r [...]

If xorriso shall be used, then the following HFS-specific options need
to be omitted:

  --netatalk
  -hfs
  -probe
  -map /srv/cdimage.ubuntu.com/debian-cd/data/hfs.map
  -part
  -no-desktop
  -hfs-bless CD1/install
  -hfs-volid Ubuntu-Server_PPC64EL_focal

Further option -sort is not supported.

  -sort /srv/cdimage.ubuntu.com/scratch/ubuntu-server/focal/daily-live/tmp/focal-ppc64el/1.weights

There is xorrisofs option

  --sort-weight-list disk_path

But the sequence of number and path in the file "disk_path" is reversed
in comparison to mkisofs -sort.
I wonder why file content sorting is applied at all. The classic reason to
avoid an old (and hopefully fixed) bug of ISOLINUX does not apply here.

Have a nice day :)

Thomas

[Paride Legovini (paride)]

xorriso now fails with (full error below):

  SORRY : Cannot make proposal to produce APM of loaded image

however this is not obvious from the logs because of a /dev/null redirect. I think it's safe to drop it, see https://github.com/canonical/subiquity/pull/900.

Full xorriso error:

$ xorriso -indev /var/cache/utah/iso/focal-live-server-ppc64el.iso -report_el_torito as_mkisofs
xorriso 1.4.8 : RockRidge filesystem manipulator, libburnia project.

xorriso : NOTE : Loading ISO image tree from LBA 0
xorriso : UPDATE : 142 nodes read in 1 seconds
Drive current: -indev '/var/cache/utah/iso/focal-live-server-ppc64el.iso'
Media current: stdio file, overwriteable
Media status : is written , is appendable
Boot record : (system area only) , MBR cyl-align-off APM
Media summary: 1 session, 610160 data blocks, 1192m data, 139g free
Volume id : 'Ubuntu-Server 20.04.2 LTS ppc64'
xorriso : SORRY : Cannot make proposal to produce APM of loaded image
-V 'Ubuntu-Server 20.04.2 LTS ppc64'
--modification-date='2021022107332800'
-partition_cyl_align off
-partition_offset 0
-append_partition 4 0x8 --interval:local_fs:1718121313d-3352666579d::'/var/cache/utah/iso/focal-live-server-ppc64el.iso'
-apm-block-size 512
-G --interval:local_fs:0s-15s:zero_mbrpt,zero_apm:'/var/cache/utah/iso/focal-live-server-ppc64el.iso'
-iso_mbr_part_type 0x96
-no-pad
xorriso : NOTE : Tolerated problem event of severity 'SORRY'
xorriso : NOTE : -return_with SORRY 32 triggered by problem severity SORRY

$ echo $?
32

[Thomas Schmitt (scdbackup)]

Hi,

Paride Legovini wrote:
> see https://github.com/canonical/subiquity/pull/900

where i see:

- opts="$(xorriso -indev ${OLD_ISO} -report_el_torito as_mkisofs 2>/dev/null)"

+ opts="$(xorriso -indev ${OLD_ISO} -report_el_torito as_mkisofs)"

Consider to reduce verbosity by xorriso command -report_about.
Like:

+ opts="$(xorriso -report_about warning -indev ${OLD_ISO} -report_el_torito as_mkisofs)"

You could raise the threshold to -report_about "sorry". But messages of
severity "WARNING" are noteworthy, too.

xorriso classifies its stderr messages by a spectrum from "DEBUG" to "FATAL".
(stderr messages without a severity prefix are of severity "NOTE".)
The commands -report_about, -return_with, and -abort_on set thresholds for
message emission, exit value, and premature program end.

This does not affect stdout of xorriso, which is considered to transfer
only result data, which were ordered by inquiry commands like
-report_el_torito or -toc.

Have a nice day :)

Thomas