Created attachment 1649210 [details]
Serial console output on s390x

Created attachment 1649211 [details]
Serial console output on aarch64 using the same kickstart

Thanks for the serial console output but we are missing info contained in the Anaconda logs which are contained in /tmp/*.log during the installation. As far as I see these are not contained even in the comment 1 link.

From the existing information it seems that for S390 we are downloading packages to RAM for some reason but in the Arm case we are downloading packages to a partition (I guess) which is preferred.

Could you please provide us Anaconda logs.

Created attachment 1649257 [details]
Serial outputs of failed install with various debug command outputs

Hello Jiří, it's quite hard to get the /tmp files as the system is not accessible after the failure. Is there any particular file you'd like to see? I tried manually running several commands in a loop via:

    echo -e "\e\t\n" > inpipe
    while :; do echo "cat /proc/meminfo" > inpipe; echo "free" > inpipe; sleep 1; done
    while :; do echo ls /tmp > inpipe; echo df -h > inpipe; sleep 1; done

and you can find the outputs attached. Unfortunatelly any other inquiries end up with:

[anaconda root@localhost ~]# cat /tmp/*.log
bash: /bin/cat: Input/output error
[anaconda root@localhost ~]# 
[anaconda root@localhost ~]# cd /tmp
[anaconda root@localhost tmp]# ls
bash: /bin/ls: Input/output error
[anaconda root@localhost tmp]# rm /tmp/*.rpm
bash: /bin/rm: Input/output error
[anaconda root@localhost tmp]# cd ..  
[anaconda root@localhost /]# df -h
Segmentation fault
[anaconda root@localhost /]# 


Also I tried at least obtaining the last available output from other ttys, here they are:


16:49:29,151 INF installation: Task started: Install the payload (15/20)
16:49:29,151 INF progress: Starting package installation process
16:49:29,247 DBG payload: apply with result True called on requirements [('package', 'lvm2', PayloadRequirement(id=lvm2, reasons=[PayloadRequirementReason(reason='storage', strong=True)])), ('package', 'xfsprogs', PayloadRequirement(id=xfsprogs, reasons=[PayloadRequirementReason(reason='storage', strong=True)])), ('package', 'e2fsprogs', PayloadRequirement(id=e2fsprogs, reasons=[PayloadRequirementReason(reason='storage', strong=True)])), ('package', 'firewalld', PayloadRequirement(id=firewalld, reasons=[PayloadRequirementReason(reason='firewall', strong=True)])), ('package', 'chrony', PayloadRequirement(id=chrony, reasons=[PayloadRequirementReason(reason='ntp', strong=False)])), ('package', 's390utils-base', PayloadRequirement(id=s390utils-base, reasons=[PayloadRequirementReason(reason='bootloader', strong=True)])), ('package', 'langpacks-en', PayloadRequirement(id=langpacks-en, reasons=[PayloadRequirementReason(reason='langpacks', strong=False)]))]
16:49:29,424 WRN misc: /usr/lib64/python3.6/site-packages/pyanaconda/payload/dnfpayload.py:593: DeprecationWarning: Attribute module_debsolv_errors is deprecated. Use module_depsolv_errors attribute instead.
  transaction_too_broken = e.error_group_specs or e.error_pkg_specs or e.module_debsolv_errors



16:49:28,303 DBG blivet:                NoDevice.setup: tmpfs ; orig: False ; status: False ; controllable: True ;
16:49:28,396 DBG blivet:                TmpFS.setup: device: tmpfs ; type: tmpfs ; status: True ;
16:49:28,404 DBG blivet:                NoDevice.setup: proc ; orig: False ; status: False ; controllable: True ;
16:49:28,526 DBG blivet:                ProcFS.setup: device: proc ; type: proc
; status: False ;
16:49:28,572 DBG blivet:                DirectoryDevice.setup: /run ; orig: False ; status: True ; controllable: True
16:49:28,726 DBG blivet:                BindFS.setup: device: /run ; type: bind
; status: False ;
16:49:28,764 DBG blivet:                NoDevice.setup: sysfs ; orig: False ; status: False ; controllable: True ;
16:49:28,886 DBG blivet:                SysFS.setup: device: sysfs ; type: sysfs ; status: False ;
16:49:28,923 DBG blivet:                NoDevice.setup: selinuxfs ; orig: False
; status: False ; controllable: True ;
16:49:29,046 DBG blivet:                SELinuxFS.setup: device: selinuxfs ; type: selinuxfs ; status: False ;



16:49:29,987 INF program: /dev/shm              1025160
16:49:29,987 INF program: /run                   967056
16:49:29,987 INF program: /sys/fs/cgroup        1025168
16:49:29,987 INF program: /                     1195048
16:49:29,987 INF program: /tmp                  1007932
16:49:29,987 INF program: /mnt/sysimage         8282512
16:49:29,987 INF program: /mnt/sysimage/boot     998044
16:49:29,987 INF program: /mnt/sysimage/dev/shm 1025168
16:49:29,987 DBG program: Return code: 0
16:49:30,143 INF program: Running... df --output=target,avail
16:49:30,147 INF program: Mounted on              Avail
16:49:30,147 INF program: /dev                  1002628
16:49:30,147 INF program: /dev/shm              1025160
16:49:30,148 INF program: /run                   967056
16:49:30,148 INF program: /sys/fs/cgroup        1025168
16:49:30,148 INF program: /                     1195048
16:49:30,148 INF program: /tmp                  1007932
16:49:30,148 INF program: /mnt/sysimage         8282512
16:49:30,148 INF program: /mnt/sysimage/boot     998044
16:49:30,148 INF program: /mnt/sysimage/dev/shm 1025168
16:49:30,148 DBG program: Return code: 0



..
Creating disklabel on /dev/sda
Creating xfs on /dev/sda1
Creating lvmpv on /dev/sda2
Creating swap on /dev/mapper/rhel-swap
Creating xfs on /dev/mapper/rhel-root
..
Running pre-installation scripts
.
Discovering realm to join
.
Running pre-installation tasks
......
Installing.
Starting package installation process
Downloading packages
Downloading 1178 RPMs, 148.72 MiB / 885.11 MiB (16%) done.
Downloading 1178 RPMs, 302.21 MiB / 885.11 MiB (34%) done.
Downloading 1178 RPMs, 450.95 MiB / 885.11 MiB (50%) done.

Pane is dead (signal 7, Thu Jan  2 16:49:37 2020)

Created attachment 1649260 [details]
Serial outputs of failed install with journalctl -f output

Additionally I tried running "journalctl -f". It's slightly corrupted due to anaconda formatting, but some info can be obtained from it. Hopefully it's useful. (note I used \e\ŧ to circle through the ttys when I assumed it's "over", so last few windows are not the journalctl related)

Based on this:

2020-01-02 12:27:10: Jan 02 17:27:09 localhost anaconda[2057]: packaging: Sufficient mountpoints found: {'/': Size (1.13970184326171875 GiB), '/mnt/sysimage': Size (7.8988189697265625 GiB)}
2020-01-02 12:27:10: Jan 02 17:27:09 localhost anaconda[2057]: packaging: Mountpoint / picked as download location


It seems that we are correctly using '/' as download location. So this shouldn't be a problem for RAM. However, there are plenty of kernel storage errors:

2020-01-02 12:27:12: [7;1HJan 02 17:27:12 localhost multipathd[1876]: sda: triggering change event to reinitialize
2020-01-02 12:27:12: Jan 02 17:27:12 localhost multipath[2652]: [1msda: failed to get udev uid: Invalid argument
2020-01-02 12:27:12: [m(BJan 02 17:27:12 localhost multipath[2652]: [1msda: failed to get sysfs uid: No data available
2020-01-02 12:27:12: [m(BJan 02 17:27:12 localhost multipath[2652]: [1msda: failed to get sgio uid: No data available
2020-01-02 12:27:12: [m(BJan 02 17:27:12 localhost multipathd[1876]: sda: failed to get udev uid: Invalid argument
2020-01-02 12:27:12: Jan 02 17:27:12 localhost multipathd[1876]: sda: failed to get sysfs uid: No data available
2020-01-02 12:27:12: Jan 02 17:27:12 localhost multipathd[1876]: sda: failed to get sgio uid: No data available
2020-01-02 12:27:12: Jan 02 17:27:12 localhost multipathd[1876]: sda: failed to get path uid
2020-01-02 12:27:12: Jan 02 17:27:12 localhost multipathd[1876]: uevent trigger error[1;24r[23;1H

2020-01-02 12:27:16: [H[1mor 1165160 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165168 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165176 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165184 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165192 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165200 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165208 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mblk_update_request: I/O error, dev loop2, sector 1165216 op 0x1:(WRITE) flags 0x0 phys_seg 1 prio class 0
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mdevice-mapper: snapshots: Invalidating snapshot: Error reading/writing.
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mEXT4-fs warning (device dm-0): ext4_end_bio:323: I/O error 10 writing to inode 21697 (offset 0 size 421888 starting block 671462)
2020-01-02 12:27:16: [m(BJan 02 17:27:16 localhost kernel: [1mBuffer I/O error on device dm-0, logical block 671360

...

I wonder why increasing memory helps you. Could that be something S390 specific?

Dan could you please look on this if the errors in the journal are expected?

But isn't '/' still an in-memory filesystem when anaconda runs (on s390x)? install.img is first downloaded, then the runtime image is mounted via a loop device (ext4 image inside a squashfs image). Other platforms use install.img in form of some disk usually, so it doesn't occupy the memory. For s390 KVM guests you should be able to use the installer ISO similarly to other platforms.

The I/O errors are symptoms of the OOM situation AFAIK. And naturally the more repos/rpms/... one adds, the more memory the VM must have. I think that when other platform would be downloading install.img, they would have similar memory requirements as s390x.

Oh damn you are correct, I thought we are in chroot already but not here. Thanks a lot for spotting this Dan.


In that case I don't quite understand why the download doesn't work? We are downloading 850MB and there is 1.1GB free space (based on df). Something is eating RAM between we pick download location and start downloading.

We have information:

2020-01-02 12:03:29: [22;1H/dev/mapper/live-rw    2.9G  1.8G  1.2G  61% /

but when the installation starts it looks like this:

2020-01-02 12:05:52: [22;1H/dev/mapper/live-rw    2.9G  2.3G  619M  79% /


It seems that the problem could be that we are making a free space check to pick download location too early so not everything is initialized.  Still, I wonder what consumes that 600MB of memory...

Lukáš, are you able to get memory consumption by processes please? Something like you already done by `df -h` but for top or similar?

(In reply to Jiri Konecny from comment #13)
> Oh damn you are correct, I thought we are in chroot already but not here.
> Thanks a lot for spotting this Dan.
> 
> 
> In that case I don't quite understand why the download doesn't work? We are
> downloading 850MB and there is 1.1GB free space (based on df). Something is
> eating RAM between we pick download location and start downloading.
> 
> We have information:
> 
> 2020-01-02 12:03:29: [22;1H/dev/mapper/live-rw    2.9G  1.8G  1.2G  61% /
> 
> but when the installation starts it looks like this:
> 
> 2020-01-02 12:05:52: [22;1H/dev/mapper/live-rw    2.9G  2.3G  619M  79% /
> 
> 
> It seems that the problem could be that we are making a free space check to
> pick download location too early so not everything is initialized.  Still, I
> wonder what consumes that 600MB of memory...
> 
> Lukáš, are you able to get memory consumption by processes please? Something
> like you already done by `df -h` but for top or similar?

Do you have a suggestion of what command should I ran to gather that info? I can execute basically anything in the background and reproducibility is 100% so it's just a matter of letting me know what would help.

(In reply to Jiri Konecny from comment #10)
> Based on this:
> 
> 2020-01-02 12:27:10: Jan 02 17:27:09 localhost anaconda[2057]: packaging:
> Sufficient mountpoints found: {'/': Size (1.13970184326171875 GiB),
> '/mnt/sysimage': Size (7.8988189697265625 GiB)}
> 2020-01-02 12:27:10: Jan 02 17:27:09 localhost anaconda[2057]: packaging:
> Mountpoint / picked as download location
> 
> 
> It seems that we are correctly using '/' as download location. So this
> shouldn't be a problem for RAM. However, there are plenty of kernel storage
> errors:

Well, using free space on '/' as a download location is very very very incorrect. Data written to '/' are stored in RAM, but free space on '/' doesn't depend on the system's RAM size. It depends on the size of rootfs.img in install.img (currently 3 GB, see related bug 1661169, where rootfs.img was enlarged from 2 to 3 GB) and the content of the image. Free space on / can be even bigger than RAM size - try to boot boot.iso in a VM with 800 MB RAM.

Possible package download locations are defined at https://github.com/rhinstaller/anaconda/blob/rhel-8/pyanaconda/payload/dnfpayload.py#L70 as:

DOWNLOAD_MPOINTS = {'/tmp',
                    '/',
                    '/var/tmp',
                    '/mnt/sysimage',
                    '/mnt/sysimage/home',
                    '/mnt/sysimage/tmp',
                    '/mnt/sysimage/var',
                    }

'/' and '/var/tmp' are the same filesystem in the install environment and must not be used IMO.
This applies to the installation environment, but it could be OK to use them for dirInstall/imageInstall.

Good thing is that we can reproduce this even on x86_64 architecture. It just about creating VM with low amount of RAM.

Note:
The reason why we are seeing this only on RHEL-8 is that installation with YUM (RHEL-7) allowed us to install packages one-by-one. Thanks to that the space requirement was just for one download package. In the Fedora case they have quite correct low size of tmpfs so it's not that easy to experience this.

Right now we have to think of the best way how to bend the algorithm.


There are two possible solutions I can think of now:

- tweak the algorithm to take into account tmpfs (look ono free output + increase requested size)
- do not download to tmpfs

(In reply to Jiri Konecny from comment #16)
...
> There are two possible solutions I can think of now:
> 
> - tweak the algorithm to take into account tmpfs (look ono free output +
> increase requested size)
> - do not download to tmpfs

I like the second option and avoid downloading to tmpfs completely. Let the kernel decide how to use free memory effectively.

BTW, this problem was reproduced on x86_64 in a VM with 1600 MB RAM, when installing from http (inst.repo=http://... on the kernel command line) with the following packages section in the kickstart file:

%packages
%end

PR: https://github.com/rhinstaller/anaconda/pull/2299

In this PR we are disabling package download to `/` and `/tmp`. However, for image and directory installation you can still use `/var/tmp` which usually on HDD so it shouldn't be a problem.

*** Bug 1776282 has been marked as a duplicate of this bug. ***

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:1584