From https://kojipkgs.fedoraproject.org//work/tasks/5352/15555352/Fedora-Cloud-Ba...
Sep 10 03:13:17 cloudhost.localdomain cloud-init[645]: 2016-09-10 03:13:17,078 - util.py[WARNING]: Failed: growpart /dev/sda 1 Sep 10 03:13:17 cloudhost.localdomain cloud-init[645]: [CLOUDINIT] util.py[DEBUG]: Failed: growpart /dev/sda 1 Traceback (most recent call last): File "/usr/lib/python3.5/site-packages/cloudinit/config/cc_growpart.py", line 109, in resize util.subp(["growpart", diskdev, partnum]) File "/usr/lib/python3.5/site-packages/cloudinit/util.py", line 1724, in subp cmd=args) cloudinit.util.ProcessExecutionError: Unexpected error while running command. Command: ['growpart', '/dev/sda', '1'] Exit code: 2 Reason: - Stdout: 'FAILED: failed to resize\n' Stderr: "attempt to resize /dev/sda failed. sfdisk output below:\n| Backup files:\n| MBR (offset 0, size 512): /tmp/growpart.PO8wWI/backup-sda-0x00000000.bak\n| \n| Disk /dev/sda: 10 GiB, 10737418240 bytes, 20971520 sectors\n| Units: sectors of 1 * 512 = 512 bytes\n| Sector size (logical/physical): 512 bytes / 512 bytes\n| I/O size (minimum/optimal): 512 bytes / 512 bytes\n| Disklabel type: dos\n| Disk identifier: 0x1ef30347\n| \n| Old situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 6291455 6289408 3G 83 Linux\n| \n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Created a new DOS disklabel with disk identifier 0x1ef30347.\n| Created a new partition 1 of type 'Linux' and of size 10 GiB.\n| /dev/sda2: \n| New situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 20971519 20969472 10G 83 Linux\n| \n| The partition table has been altered.\n| Calling ioctl() to re-read partition table.\n| Re-reading the partition table failed.: Device or resource busy\n| The kernel still uses the old table. The new table will be used at the next reboot or after you run partprobe(8) or kpartx(8).\n***** WARNING: Resize failed, attempting to revert ******\n512+0 records in\n512+0 records out\n512 bytes copied, 0.000400551 s, 1.3 MB/s\n***** Appears to have gone OK ****\n" Sep 10 03:13:17 cloudhost.localdomain cloud-init[645]: [CLOUDINIT] util.py[DEBUG]: resize_devices took 0.127 seconds Sep 10 03:13:17 cloudhost.localdomain cloud-init[645]: [CLOUDINIT] cc_growpart.py[DEBUG]: '/' FAILED: failed to resize: disk=/dev/sda, ptnum=1: Unexpected error while running command. Command: ['growpart', '/dev/sda', '1'] Exit code: 2 Reason: - Stdout: 'FAILED: failed to resize\n' Stderr: "attempt to resize /dev/sda failed. sfdisk output below:\n| Backup files:\n| MBR (offset 0, size 512): /tmp/growpart.PO8wWI/backup-sda-0x00000000.bak\n| \n| Disk /dev/sda: 10 GiB, 10737418240 bytes, 20971520 sectors\n| Units: sectors of 1 * 512 = 512 bytes\n| Sector size (logical/physical): 512 bytes / 512 bytes\n| I/O size (minimum/optimal): 512 bytes / 512 bytes\n| Disklabel type: dos\n| Disk identifier: 0x1ef30347\n| \n| Old situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 6291455 6289408 3G 83 Linux\n| \n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Created a new DOS disklabel with disk identifier 0x1ef30347.\n| Created a new partition 1 of type 'Linux' and of size 10 GiB.\n| /dev/sda2: \n| New situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 20971519 20969472 10G 83 Linux\n| \n| The partition table has been altered.\n| Calling ioctl() to re-read partition table.\n| Re-reading the partition table failed.: Device or resource busy\n| The kernel still uses the old table. The new table will be used at the next reboot or after you run partprobe(8) or kpartx(8).\n***** WARNING: Resize failed, attempting to revert ******\n512+0 records in\n512+0 records out\n512 bytes copied, 0.000400551 s, 1.3 MB/s\n***** Appears to have gone OK ****\n"
Should I open a bug for this? Can we get someone to look at it/work on it?
Dusty
On Fri, 2016-09-09 at 23:28 -0400, Dusty Mabe wrote:
From https://kojipkgs.fedoraproject.org//work/tasks/5352/15555352/Fedora-Cloud-Ba...
It's a lot easier to read if you replace all the /n 's with actual line breaks...
On Fri, Sep 9, 2016 at 9:28 PM, Dusty Mabe dusty@dustymabe.com wrote:
Stderr: "attempt to resize /dev/sda failed. sfdisk output below:\n| Backup files:\n| MBR (offset 0, size 512): /tmp/growpart.PO8wWI/backup-sda-0x00000000.bak\n| \n| Disk /dev/sda: 10 GiB, 10737418240 bytes, 20971520 sectors\n| Units: sectors of 1 * 512 = 512 bytes\n| Sector size (logical/physical): 512 bytes / 512 bytes\n| I/O size (minimum/optimal): 512 bytes / 512 bytes\n| Disklabel type: dos\n| Disk identifier: 0x1ef30347\n| \n| Old situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 6291455 6289408 3G 83 Linux\n|
Ok so it starts out as 6289408/2048= 3071MiB (or 3G)
Created a new partition 1 of type 'Linux' and of size 10 GiB.\n| /dev/sda2: \n|
New situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 20971519 20969472 10G 83 Linux\n| \n|
New size. But what about sda2? It said it was creating a new partition sda2, but not specifying its size, only specifying the new size of sda1.
The partition table has been altered.\n| Calling ioctl() to re-read partition table.\n| Re-reading the partition table failed.: Device or resource busy\n| The kernel still uses the old table. The new table will be used at the next reboot or after you run partprobe(8) or kpartx(8).\n
Something isn't calling partprobe? Or there's a kernel error in re-reading the device? dmesg would help, maybe.
***** WARNING: Resize failed, attempting to revert ******\n512+0 records in\n512+0 records out\n512 bytes copied, 0.000400551 s, 1.3 MB/s\n***** Appears to have gone OK ****\n"
And if we are to believe this, it changed the partition table back to the Old Situation.
Sep 10 03:13:17 cloudhost.localdomain cloud-init[645]: [CLOUDINIT] util.py[DEBUG]: resize_devices took 0.127 seconds Sep 10 03:13:17 cloudhost.localdomain cloud-init[645]: [CLOUDINIT] cc_growpart.py[DEBUG]: '/' FAILED: failed to resize: disk=/dev/sda, ptnum=1: Unexpected error while running command. Command: ['growpart', '/dev/sda', '1'] Exit code: 2 Reason: - Stdout: 'FAILED: failed to resize\n' Stderr: "attempt to resize /dev/sda failed. sfdisk output below:\n| Backup files:\n| MBR (offset 0, size 512): /tmp/growpart.PO8wWI/backup-sda-0x00000000.bak\n| \n| Disk /dev/sda: 10 GiB, 10737418240 bytes, 20971520 sectors\n| Units: sectors of 1 * 512 = 512 bytes\n| Sector size (logical/physical): 512 bytes / 512 bytes\n| I/O size (minimum/optimal): 512 bytes / 512 bytes\n| Disklabel type: dos\n| Disk identifier: 0x1ef30347\n| \n| Old situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 6291455 6289408 3G 83 Linux\n| \n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Script header accepted.\n| >>> Created a new DOS disklabel with disk identifier 0x1ef30347.\n| Created a new partition 1 of type 'Linux' and of size 10 GiB.\n| /dev/sda2: \n| New situation:\n| \n| Device Boot Start End Sectors Size Id Type\n| /dev/sda1 * 2048 20971519 20969472 10G 83 Linux\n| \n| The partition table has been altered.\n| Calling ioctl() to re-read partition table.\n| Re-reading the partition table failed.: Device or resource busy\n| The kernel still uses the old table. The new table will be used at the next reboot or after you run partprobe(8) or kpartx(8).\n***** WARNING: Resize failed, attempting to revert ******\n512+0 records in\n512+0 records out\n512 bytes copied, 0.000400551 s, 1.3 MB/s\n***** Appears to have gone OK ****\n"
And that just looks like a 2nd attempt which also fails.
Should I open a bug for this? Can we get someone to look at it/work on it?
Yes, and I think it needs a dmesg in case partprobe was called but that failed for some reason. And then need to look at the cloud-init code and see if partprobe is being called. This is not the best log, it doesn't report the actual commands its using and the exit code for each command. So we're left wondering if partprobe was called or not. Maybe it's being called but is missing in the image?
Could be related this bug, I see the same error there after Disks changes partitioning, and the old partition table is being used. A feature for Fedora 25 is udisks is replaced by storaged, so this could be part of that problem. But I have no idea why could-init would be using udisks or storaged, so this might be a goose chase.
Error setting partition type after formatting https://bugzilla.redhat.com/show_bug.cgi?id=1374334
Chris Murphy
On Sat, Sep 10, 2016 at 12:05 PM, Chris Murphy lists@colorremedies.com wrote:
Could be related this bug, I see the same error there after Disks changes partitioning, and the old partition table is being used. A feature for Fedora 25 is udisks is replaced by storaged, so this could be part of that problem. But I have no idea why could-init would be using udisks or storaged, so this might be a goose chase.
Error setting partition type after formatting https://bugzilla.redhat.com/show_bug.cgi?id=1374334
Could be both cloud-init and this storaged bug are hitting the same lower level bug, causing the kernel to not get an updated partition table (via partprobe)... the journal output in that bug isn't enlightening, there are no kernel messages. One reason it'd fail is if something has mounted any file system on the device that's having its partition modified, that'd make it busy, and partprobe tends to fail in that case.
On 09/10/2016 12:47 PM, Chris Murphy wrote:
On Fri, Sep 9, 2016 at 9:28 PM, Dusty Mabe dusty@dustymabe.com wrote:
Should I open a bug for this? Can we get someone to look at it/work on it?
Yes, and I think it needs a dmesg in case partprobe was called but that failed for some reason. And then need to look at the cloud-init code and see if partprobe is being called. This is not the best log, it doesn't report the actual commands its using and the exit code for each command. So we're left wondering if partprobe was called or not. Maybe it's being called but is missing in the image?
I opened a bug here and added some more information to it:
On 09/11/2016 12:22 AM, Dusty Mabe wrote:
On 09/10/2016 12:47 PM, Chris Murphy wrote:
On Fri, Sep 9, 2016 at 9:28 PM, Dusty Mabe dusty@dustymabe.com wrote:
Should I open a bug for this? Can we get someone to look at it/work on it?
Yes, and I think it needs a dmesg in case partprobe was called but that failed for some reason. And then need to look at the cloud-init code and see if partprobe is being called. This is not the best log, it doesn't report the actual commands its using and the exit code for each command. So we're left wondering if partprobe was called or not. Maybe it's being called but is missing in the image?
I opened a bug here and added some more information to it:
and.. this has actually already been reported and the fix is in updates-testing.
On Sat, Sep 10, 2016 at 10:45 PM, Dusty Mabe dusty@dustymabe.com wrote:
On 09/11/2016 12:22 AM, Dusty Mabe wrote:
On 09/10/2016 12:47 PM, Chris Murphy wrote:
On Fri, Sep 9, 2016 at 9:28 PM, Dusty Mabe dusty@dustymabe.com wrote:
Should I open a bug for this? Can we get someone to look at it/work on it?
Yes, and I think it needs a dmesg in case partprobe was called but that failed for some reason. And then need to look at the cloud-init code and see if partprobe is being called. This is not the best log, it doesn't report the actual commands its using and the exit code for each command. So we're left wondering if partprobe was called or not. Maybe it's being called but is missing in the image?
I opened a bug here and added some more information to it:
and.. this has actually already been reported and the fix is in updates-testing.
Good catch. Looks like it affects udisks2/storaged as well.