growpart not working in Fedora 25 cloud base

[Dusty Mabe]

From
https://kojipkgs.fedoraproject.org//work/tasks/5352/15555352/Fedora-Cloud...



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

[Adam Williamson]

On Fri, 2016-09-09 at 23:28 -0400, Dusty Mabe wrote:
>  From
> https://kojipkgs.fedoraproject.org//work/tasks/5352/15555352/Fedora-Cloud...
It's a lot easier to read if you replace all the /n 's with actual line
breaks...
-- 
Adam Williamson
Fedora QA Community Monkey
IRC: adamw | Twitter: AdamW_Fedora | XMPP: adamw AT happyassassin . net
http://www.happyassassin.net

[Chris Murphy]

On Fri, Sep 9, 2016 at 9:28 PM, Dusty Mabe <dusty(a)dustymabe.com&gt; 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?



-- 
Chris Murphy

[Chris Murphy]

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

[Chris Murphy]

On Sat, Sep 10, 2016 at 12:05 PM, Chris Murphy <lists(a)colorremedies.com&gt; 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.

-- 
Chris Murphy

[Dusty Mabe]

On 09/10/2016 12:47 PM, Chris Murphy wrote:
>  On Fri, Sep 9, 2016 at 9:28 PM, Dusty Mabe
> <dusty(a)dustymabe.com&gt; 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:

https://bugzilla.redhat.com/show_bug.cgi?id=1374968

[Dusty Mabe]

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(a)dustymabe.com&gt; 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:
>  
>  https://bugzilla.redhat.com/show_bug.cgi?id=1374968
>   
and.. this has actually already been reported and the fix is in
updates-testing.

https://bugzilla.redhat.com/show_bug.cgi?id=1371761

[Chris Murphy]

On Sat, Sep 10, 2016 at 10:45 PM, Dusty Mabe <dusty(a)dustymabe.com&gt; 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(a)dustymabe.com&gt; 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:
> >
> > https://bugzilla.redhat.com/show_bug.cgi?id=1374968
> >
>
>  and.. this has actually already been reported and the fix is in
>  updates-testing.
>
>  https://bugzilla.redhat.com/show_bug.cgi?id=1371761 
Good catch. Looks like it affects udisks2/storaged as well.


-- 
Chris Murphy