Failing to bringup Chrome system image with downstream kernel boot image

[pva...@codeaurora.org]

I am trying to bringup Chrome system image with my downstream kernel boot image. I see following error:

[    6.653727] random: init: uninitialized urandom read (12 bytes read)

[    6.688824] job-filter (194) used greatest stack depth: 11856 bytes left

[    6.781102] mkdir (203) used greatest stack depth: 11728 bytes left

[    6.818881] msm-dwc3 7580000.ssusb: DWC3 in low power mode

[    6.958485] init: udev pre-start process (206) killed by ABRT signal

[    6.985651] Unsafe core_pattern used with fs.suid_dumpable=2.

[    6.985651] Pipe handler or fully qualified core dump path required.

[    6.985651] Set kernel.core_pattern before fs.suid_dumpable.

[    7.107315] grep (227) used greatest stack depth: 11584 bytes left

[    7.208702] chromeos-boot-alert: self_repair

chromeos-boot-alert: self_repair

[    7.268999] msm_rpm_flush_requests: Error: more than 24 requests are buffered

Can someone please help

[Doug Anderson]

Hi,

When you say "downstream kernel boot image", I assume this is a kernel that you can't share with us, so it will be uber hard to debug this for you.

That being said, the "chromeos-boot-alert: self_repair" is telling.  Previously I used these instructions for debugging problems like that (replace "/dev/ttyMSM0" with your serial console):

---

1. Make sure you build your image without rootfs verification (AKA pass --noenable_rootfs_verification to build_image)

2. Stick your USB disk in your PC

3. mkdir /tmp/m; sudo mount mount /dev/sdX3 /tmp/m

4. In "/tmp/m/etc/init/startup.conf", change the "exec chromos_startup" to:

script

        chromeos_startup > /dev/ttyMSM0 2>&1

end script

5. In "/tmp/m/sbin/chromeos_startup", add "set -x" somewhere near the top

---

When you do this, you'll see all the shell scripts run by chromeos_startup spit out to the serial port...

===

I have often seen problems like this when you have options missing from your kernel config.  You could try using the config generated by "./chromeos/scripts/kernelconfig genconfig" in the Chrome OS kernel for a system similar to yours.  You could also checkout one of the "fallback" configs (used for building upstream kernels) at <https://chromium.googlesource.com/chromiumos/overlays/chromiumos-overlay/+/master/eclass/cros-kernel/>

Good luck!

-Doug

--
--
Chromium OS Developers mailing list: chromiu...@chromium.org
View archives, change email options, or unsubscribe:
https://groups.google.com/a/chromium.org/group/chromium-os-dev

[pva...@codeaurora.org]

As I see some security policy related errors, I am making DISABLE_STATEFUL_SECURITY_HARDENING as true for now.

I see the output as below and it stuck. 

+ UNDO_MOUNTS=

+ mount -n -t debugfs -o nodev,noexec,nosuid,mode=0750,uid=0,gid=debugfs-access debugfs /sys/kernel/debug

+ bootstat pre-startup

+ . /usr/share/cros/startup_utils.sh

+ mkdir -p /dev/pts /dev/shm

+ mount -n -t tmpfs -o nodev,noexec,nosuid shmfs /dev/shm

+ mount -n -t devpts -o noexec,nosuid,gid=5,mode=0620 devpts /dev/pts

+ [ -d /sys/kernel/config ]

+ mount -n -t configfs -o  nodev,nosuid,noexec,mode=0750 configfs /sys/kernel/config

[    7.186777] init: udev pre-start process (207) killed by ABRT signal

+ DISABLE_STATEFUL_SECURITY_HARDENING=true

+ [ true = false ]

+ sysctl -q --system

[    7.223923] Unsafe core_pattern used with fs.suid_dumpable=2.

[    7.223923] Pipe handler or fully qualified core dump path required.

[    7.223923] Set kernel.core_pattern before fs.suid_dumpable.

sysctl: setting key "kernel.sched_rt_runtime_us": Invalid argument

+ crossystem cros_debug?1

+ CROS_DEBUG=1

+ [ 1 -eq 1 ]

+ . /usr/share/cros/dev_utils.sh

+ STATEFUL_PARTITION=/mnt/stateful_partition

+ MOUNTDIRS=

  db/pkg

  lib/portage

+ [ -f /usr/share/cros/test_utils.sh ]

+ . /usr/share/cros/test_utils.sh

+ . /usr/share/cros/factory_utils.sh

+ FACTORY_DIR=/mnt/stateful_partition/dev_image/factory

+ POWER_OVERRIDE_DIR=/run/lock/power_override

+ mkdir -p /run/lock/power_override

+ chmod 1777 /run/lock/power_override

+ rootdev -s

+ ROOT_DEV=/dev/mmcblk0p22

+ ROOTDEV_RET_CODE=0

+ echo /dev/mmcblk0p22

+ sed s/[0-9_]*$//

+ ROOTDEV_TYPE=/dev/mmcblk0p

+ ROOTDEV_NAME=mmcblk0p

+ cat /sys/block/mmcblk0p/removable

cat: /sys/block/mmcblk0p/removable: No such file or directory

+ ROOTDEV_REMOVABLE=

+ . /usr/sbin/write_gpt.sh

+ type numsectors

+ locate_gpt

+ [ -z  ]

+ [ -x /usr/bin/cgpt ]

+ GPT=/usr/bin/cgpt

+ ROOTFS_PARTITION_SIZE=2684354560

+ [  = 1 ]

+ load_base_vars

+ DEFAULT_ROOTDEV=/sys/devices/platform/fe330000.sdhci/mmc_host/mmc*/mmc*/block/mmcblk*

+ PARTITION_SIZE_RWFW=8388608

+ RESERVED_EBS_RWFW=0

+ DATA_SIZE_RWFW=8388608

+ FORMAT_RWFW=

+ FS_FORMAT_RWFW=

+ FS_OPTIONS_RWFW=

+ PARTITION_NUM_RWFW=11

+ PARTITION_SIZE_11=8388608

+ RESERVED_EBS_11=0

+ DATA_SIZE_11=8388608

+ FORMAT_11=

+ FS_FORMAT_11=

+ FS_OPTIONS_11=

+ PARTITION_NUM_11=11

+ PARTITION_SIZE_KERN_C=512

+ RESERVED_EBS_KERN_C=0

+ DATA_SIZE_KERN_C=512

+ FORMAT_KERN_C=

+ FS_FORMAT_KERN_C=

+ FS_OPTIONS_KERN_C=

+ PARTITION_NUM_KERN_C=6

+ PARTITION_SIZE_6=512

+ RESERVED_EBS_6=0

+ DATA_SIZE_6=512

+ FORMAT_6=

+ FS_FORMAT_6=

+ FS_OPTIONS_6=

+ PARTITION_NUM_6=6

+ PARTITION_SIZE_ROOT_C=512

+ RESERVED_EBS_ROOT_C=0

+ DATA_SIZE_ROOT_C=512

+ FORMAT_ROOT_C=

+ FS_FORMAT_ROOT_C=

+ FS_OPTIONS_ROOT_C=

+ PARTITION_NUM_ROOT_C=7

+ PARTITION_SIZE_7=512

+ RESERVED_EBS_7=0

+ DATA_SIZE_7=512

+ FORMAT_7=

+ FS_FORMAT_7=

+ FS_OPTIONS_7=

+ PARTITION_NUM_7=7

+ PARTITION_SIZE_RESERVED=512

+ RESERVED_EBS_RESERVED=0

+ DATA_SIZE_RESERVED=512

+ FORMAT_RESERVED=

+ FS_FORMAT_RESERVED=

+ FS_OPTIONS_RESERVED=

+ PARTITION_NUM_RESERVED=9

+ PARTITION_SIZE_9=512

+ RESERVED_EBS_9=0

+ DATA_SIZE_9=512

+ FORMAT_9=

+ FS_FORMAT_9=

+ FS_OPTIONS_9=

+ PARTITION_NUM_9=9

+ PARTITION_SIZE_RESERVED=512

+ RESERVED_EBS_RESERVED=0

+ DATA_SIZE_RESERVED=512

+ FORMAT_RESERVED=

+ FS_FORMAT_RESERVED=

+ FS_OPTIONS_RESERVED=

+ PARTITION_NUM_RESERVED=10

+ PARTITION_SIZE_10=512

+ RESERVED_EBS_10=0

+ DATA_SIZE_10=512

+ FORMAT_10=

+ FS_FORMAT_10=

+ FS_OPTIONS_10=

+ PARTITION_NUM_10=10

+ PARTITION_SIZE_KERN_A=16777216

+ RESERVED_EBS_KERN_A=0

+ DATA_SIZE_KERN_A=16777216

+ FORMAT_KERN_A=

+ FS_FORMAT_KERN_A=

+ FS_OPTIONS_KERN_A=

+ PARTITION_NUM_KERN_A=2

+ PARTITION_SIZE_2=16777216

+ RESERVED_EBS_2=0

+ DATA_SIZE_2=16777216

+ FORMAT_2=

+ FS_FORMAT_2=

+ FS_OPTIONS_2=

+ PARTITION_NUM_2=2

+ PARTITION_SIZE_KERN_B=16777216

+ RESERVED_EBS_KERN_B=0

+ DATA_SIZE_KERN_B=16777216

+ FORMAT_KERN_B=

+ FS_FORMAT_KERN_B=

+ FS_OPTIONS_KERN_B=

+ PARTITION_NUM_KERN_B=4

+ PARTITION_SIZE_4=16777216

+ RESERVED_EBS_4=0

+ DATA_SIZE_4=16777216

+ FORMAT_4=

+ FS_FORMAT_4=

+ FS_OPTIONS_4=

+ PARTITION_NUM_4=4

+ PARTITION_SIZE_OEM=16777216

+ RESERVED_EBS_OEM=0

+ DATA_SIZE_OEM=16777216

+ FORMAT_OEM=

+ FS_FORMAT_OEM=ext4

+ FS_OPTIONS_OEM=

+ PARTITION_NUM_OEM=48

+ PARTITION_SIZE_8=16777216

+ RESERVED_EBS_8=0

+ DATA_SIZE_8=16777216

+ FORMAT_8=

+ FS_FORMAT_8=ext4

+ FS_OPTIONS_8=

+ PARTITION_NUM_8=8

+ PARTITION_SIZE_EFI_SYSTEM=33554432

+ RESERVED_EBS_EFI_SYSTEM=0

+ DATA_SIZE_EFI_SYSTEM=33554432

+ FORMAT_EFI_SYSTEM=

+ FS[    7.576609] EXT4-fs (mmcblk0p49): recovery complete

[    7.581483] EXT4-fs (mmcblk0p49): mounted filesystem with ordered data mode. Opts: commit=600

_FORMAT_EFI_SYSTEM=vfat

+ FS_OPTIONS_EFI_SYSTEM=

+ PARTITION_NUM_EFI_SYSTEM=12

+ PARTITION_SIZE_12=33554432

+ RESERVED_EBS_12=0

+ DATA_SIZE_12=33554432

+ FORMAT_12=

+ FS_FORMAT_12=vfat

+ FS_OPTIONS_12=

+ PARTITION_NUM_12=12

+ PARTITION_SIZE_ROOT_B=2147483648

+ RESERVED_EBS_ROOT_B=0

+ DATA_SIZE_ROOT_B=2147483648

+ FORMAT_ROOT_B=

+ FS_FORMAT_ROOT_B=

+ FS_OPTIONS_ROOT_B=

+ PARTITION_NUM_ROOT_B=5

+ PARTITION_SIZE_5=2147483648

+ RESERVED_EBS_5=0

+ DATA_SIZE_5=2147483648

+ FORMAT_5=

+ FS_FORM

[    7.633998] EXT4-fs (mmcblk0p48): mounted filesystem with ordered data mode. Opts: (null)

AT_5=

+ FS_OPTIONS_5=

+ PARTITION_NUM_5=5

+ PARTITION_SIZE_ROOT_A=2684354560

+ RESERVED_EBS_ROOT_A=0

+ DATA_SIZE_ROOT_A=2097152000

+ FORMAT_ROOT_A=

+ FS_FORMAT_ROOT_A=ext2

+ FS_OPTIONS_ROOT_A=

+ PARTITION_NUM_ROOT_A=3

+ PARTITION_SIZE_3=2684354560

+ RESERVED_EBS_3=0

+ DATA_SIZE_3=2097152000

+ FORMAT_3=

+ FS_FORMAT_3=ext2

+ FS_OPTIONS_3=

+ PARTITION_NUM_3=3

+ PARTITION_SIZE_STATE=2147483648

+ RESERVED_EBS_STATE=0

+ DATA_SIZE_STATE=2147483648

+ FORMAT_STATE=

+ FS_FORMAT_STATE=ext4

+ FS_OPTIONS_STATE=

+ PARTITION_NUM_STATE=49

+ PARTITION_SIZE_1=2147483648

+ RESERVED_EBS_1=0

+ DATA_SIZE_1=2147483648

+ FORMAT_1=

+ FS_FORMAT_1=ext4

+ FS_OPTIONS_1=

+ PARTITION_NUM_1=1

+ LSM_INODE_POLICIES=/sys/kernel/security/chromiumos/inode_security_policies

+ STATE_DEV=

+ [ 0 = 0 -a /dev/mmcblk0p != /dev/ram ]

+ STATE_FLAGS=nodev,noexec,nosuid,noatime

+ [  = ubi ]

+ sysctl -n vm.dirty_expire_centisecs

+ DIRTY_EXPIRE_CENTISECS=60000

+ COMMIT_INTERVAL=600

+ STATE_DEV=/dev/mmcblk0p49

+ STATE_FLAGS=nodev,noexec,nosuid,noatime,commit=600

+ [ ext4 = ext4 ]

+ grep -qe ^Filesystem features:.* encrypt.*

+ dumpe2fs -h /dev/mmcblk0p49

+ ext4_dir_encryption_supported

+ local direncryption_enabled=false

+ false

+ [ ext4 = ext4 ]

+ + dumpe2fsgrep -h -qe /dev/mmcblk0p49 ^Reserved blocks gid.*20119

+ [ -d /proc/sys/fs/quota ]

+ + dumpe2fsgrep -h -qe /dev/mmcblk0p49 ^Filesystem features:.* quota.*

+ mount -n -t ext4 -o nodev,noexec,nosuid,noatime,commit=600 /dev/mmcblk0p49 /mnt/stateful_partition

+ [ true = false ]

+ OEM_FLAGS=ro,nodev,noexec,nosuid

+ [  = ubi ]

+ OEM_DEV=/dev/mmcblk0p48

+ mount -n -t ext4 -o ro,nodev,noexec,nosuid /dev/mmcblk0p48 /usr/share/oem

+ sanity_check_clock

+ local year=2017

+ local base_secs=1483228800

+ date -u +%s

+ [ 19 -lt 1483228800 ]

+ date -u 010200002017

Mon Jan  2 00:00:00 UTC 2017

+ DEV_MODE_FILE=/mnt/stateful_partition/.developer_mode

+ INSTALL_ATTRIBUTES_FILE=/mnt/stateful_partition/home/.shadow/install_attributes.pb

+ dev_check_block_dev_mode /mnt/stateful_partition/.developer_mode

+ crossystem devsw_boot?1 debug_build?0 recovery_reason?0

Unable to open FDT property vboot-shared-data

+ return

+ RESET_FILE=/mnt/stateful_partition/factory_install_reset

+ [ -O /mnt/stateful_partition/factory_install_reset ]

+ [ -z /dev/mmcblk0p49 ]

+ dev_is_debug_build

[    7.848373] msm-dwc3 7580000.ssusb: DWC3 in low power mode

+ crossystem debug_build?1

+ :

+ [ -O /mnt/stateful_partition/factory_install_reset ]

+ dev_update_stateful_partition

+ local stateful_update_file=/mnt/stateful_partition/.update_available

+ [ ! -f /mnt/stateful_partition/.update_available ]

+ return

+ mkdir -p -m 0755 /mnt/stateful_partition/home

+ check_directory /mnt/stateful_partition/home

+ local path=/mnt/stateful_partition/home

+ [ -L home ]

+ [ ! -d /mnt/stateful_partition/home ]

+ mkdir -p -m 0755 /mnt/stateful_partition/home/chronos

+ check_directory /mnt/stateful_partition/home/chronos

+ local path=/mnt/stateful_partition/home/chronos

+ [ -L home/chronos ]

+ [ ! -d /mnt/stateful_partition/home/chronos ]

+ mkdir -p -m 0755 /mnt/stateful_partition/home/root

+ check_directory /mnt/stateful_partition/home/root

+ local path=/mnt/stateful_partition/home/root

+ [ -L home/root ]

+ [ ! -d /mnt/stateful_partition/home/root ]

+ mkdir -p -m 0755 /mnt/stateful_partition/home/user

+ check_directory /mnt/stateful_partition/home/user

+ local path=/mnt/stateful_partition/home/user

+ [ -L home/user ]

+ [ ! -d /mnt/stateful_partition/home/user ]

+ mkdir -p -m 0755 /mnt/stateful_partition/unencrypted

+ check_directory /mnt/stateful_partition/unencrypted

+ local path=/mnt/stateful_partition/unencrypted

+ [ -L unencrypted ]

+ [ ! -d /mnt/stateful_partition/unencrypted ]

+ mkdir -p -m 0755 /mnt/stateful_partition/unencrypted/cache

+ check_directory /mnt/stateful_partition/unencrypted/cache

+ local path=/mnt/stateful_partition/unencrypted/cache

+ [ -L unencrypted/cache ]

+ [ ! -d /mnt/stateful_partition/unencrypted/cache ]

+ mkdir -p -m 0755 /mnt/stateful_partition/unencrypted/preserve

+ check_directory /mnt/stateful_partition/unencrypted/preserve

+ local path=/mnt/stateful_partition/unencrypted/preserve

+ [ -L unencrypted/preserve ]

+ [ ! -d /mnt/stateful_partition/unencrypted/preserve ]

+ mount_or_fail --bind /mnt/stateful_partition/home /home

+ local mount_point

+ mount -c -n --bind /mnt/stateful_partition/home /home

+ shift 2

+ remember_mount /home

+ UNDO_MOUNTS=/home 

+ return

+ remember_mount /var

+ UNDO_MOUNTS=/var /home 

+ remember_mount /home/chronos

+ UNDO_MOUNTS=/home/chronos /var /home 

+ mkdir -p /mnt/stateful_partition/var

+ mount -n --bind /mnt/stateful_partition/var /var

+ mount -n --bind /mnt/stateful_partition/home/chronos /home/chronos

+ is_var_full

+ + grep -E -odf [0-9]+ -k

 --output=avail /var

+ local var_avail=1872392

+ [ 1872392 -lt 10000 ]

+ dev_gather_logs

+ local lab_preserve_logs=/mnt/stateful_partition/.gatherme

+ local prior_log_dir=/mnt/stateful_partition/unencrypted/prior_logs

+ local log_path

+ [ ! -f /mnt/stateful_partition/.gatherme ]

+ return

+ DISABLE_STATEFUL_SECURITY_HARDENING=true

+ [ true = false ]

+ rm -rf /var/run /var/lock

+ mkdir -m 0755 /var/run /var/lock

+ mount -o bind /run /var/run

+ mount -o bind /run/lock /var/lock

+ mkdir -p -m 0755 /var/cache /var/db /var/empty /var/log/metrics /var/spool /var/tmp /var/lib/misc

+ check_directory /var/cache

+ local path=/var/cache

+ [ -L /var/cache ]

+ [ ! -d /var/cache ]

+ check_directory /var/db

+ local path=/var/db

+ [ -L /var/db ]

+ [ ! -d /var/db ]

+ check_directory /var/empty

+ local path=/var/empty

+ [ -L /var/empty ]

+ [ ! -d /var/empty ]

+ check_directory /var/log

+ local path=/var/log

+ [ -L /var/log ]

+ [ ! -d /var/log ]

+ check_directory /var/log/metrics

+ local path=/var/log/metrics

+ [ -L /var/log/metrics ]

+ [ ! -d /var/log/metrics ]

+ check_directory /var/spool

+ local path=/var/spool

+ [ -L /var/spool ]

+ [ ! -d /var/spool ]

+ check_directory /var/tmp

+ local path=/var/tmp

+ [ -L /var/tmp ]

+ [ ! -d /var/tmp ]

+ check_directory /var/lib

+ local path=/var/lib

+ [ -L /var/lib ]

+ [ ! -d /var/lib ]

+ check_directory /var/lib/misc

+ local path=/var/lib/misc

+ [ -L /var/lib/misc ]

+ [ ! -d /var/lib/misc ]

+ check_directory /home/chronos

+ local path=/home/chronos

+ [ -L /home/chronos ]

+ [ ! -d /home/chronos ]

+ check_directory /home/root

+ local path=/home/root

+ [ -L /home/root ]

+ [ ! -d /home/root ]

+ chmod 1777 /var/tmp

+ chmod 1771 /home/root

+ chown chronos:chronos /home/chronos /var/log/metrics

+ chgrp syslog /var/log

+ chmod 1775 /var/log

+ chmod 0755 /var/cache /var/db /var/empty /var/spool /var/lib /var/lib/misc

chmod: changing permissions of '/var/empty': Operation not permitted

+ chattr +i /var/empty

+ mount --make-shared -n -t tmpfs -o nodev,noexec,nosuid media /media

+ dev_mount_packages

+ mkdir -p /var/log/asan

+ chmod 1777 /var/log/asan

+ cat /proc/mounts

+ [ ! -d /dev_image ]

+ mkdir -p -m 0755 /mnt/stateful_partition/dev_image

+ mount_or_fail --bind /mnt/stateful_partition/dev_image /usr/local

+ local mount_point

+ mount -c -n --bind /mnt/stateful_partition/dev_image /usr/local

+ shift [    8.275335] EXT4-fs (mmcblk0p49): re-mounted. Opts: resgid=20119,commit=600,data=ordered

2

+ remember_mount /usr/local

+ UNDO_MOUNTS=/usr/local /home/chronos /var /home 

+ return

+ mount -n -o remount,exec,suid /usr/local

+ local base=/mnt/stateful_partition/var_overlay

+ [ -d /mnt/stateful_partition/var_overlay ]

+ [ true = false ]

+ bootstat post-startup

+ exit 0

[    8.366278] init: ureadahead main process (279) terminated with status 5

[    8.384996] msm_rpm_flush_requests: Error: more than 24 requests are buffered

[Doug Anderson]

Hi,

On Fri, Aug 24, 2018 at 6:12 AM, <pva...@codeaurora.org> wrote:

As I see some security policy related errors, I am making DISABLE_STATEFUL_SECURITY_HARDENING as true for now.

I see the output as below and it stuck. 

It seems like you're not getting the self_repair anymore.  Is that right?  Now the question is why it's getting stuck.

Strangely enough when I synced down today I found my device getting stuck and then rebooting.  The build I made yesterday didn't have that problem?!?!  I didn't manage to debug this today and not sure what's going on.

-Doug

[Doug Anderson]

Hi,

I tracked down my problem of it getting stuck / hanging at bootup.  In case they are the same as yours, feel free to check out <https://bugs.chromium.org/p/chromium/issues/detail?id=878145>.

-Doug

[pva...@codeaurora.org]

I see these errors:

Unable to open FDT property vboot-shared-data

Unable to open FDT property nonvolatile-context-lba

Unable to open FDT property nonvolatile-context-offset

Unable to open FDT property nonvolatile-context-size

I am not sure if these are real issues.

[Doug Anderson]

Hi,

On Tue, Aug 28, 2018 at 1:09 AM, <pva...@codeaurora.org> wrote:

I see these errors:

Unable to open FDT property vboot-shared-data

Unable to open FDT property nonvolatile-context-lba

Unable to open FDT property nonvolatile-context-offset

Unable to open FDT property nonvolatile-context-size

I am not sure if these are real issues.

Are they causing problems?  Seems likely this is just because you're using a BIOS that doesn't set these up.

-Doug 

[pva...@codeaurora.org]

Hi,

After sync to the latest code base and some tweaks, I see these errors resolved. But I am now stuck starting syslogd.

I see following errors. I am not sure what is going wrong here.

[    5.215950] ALSA device lis󙞠  5.231897] EXT4-fs (mmcblk0p22): mounted filesystem without journal. Opts: (null)

[    5.232012] VFS: Mounted root (ext4 filesystem) readonly on device 179:22.

[    5.241345] devtmpfs: mounted

[    5.248656] Freeing unused kernel memory: 2048K

[    5.409704] random: init: uninitialized urandom read (12 bytes read)

[    5.437612] job-filter (218) used greatest stack depth: 11600 bytes left

[    5.536384] mkdir (226) used greatest stack depth: 11456 bytes left

[    5.713833] udevd[236]: starting version 225

[    5.754343] random: udevd: uninitialized urandom read (16 bytes read)

[    5.757596] random: udevd: uninitialized urandom read (16 bytes read)

sysctl: setting key "kernel.sched_rt_runtime_us": Invalid argument

[    5.762322] Unsafe core_pattern used with fs.suid_dumpable=2.

[    5.762322] Pipe handler or fully qualified core dump path required.

[    5.762322] Set kernel.core_pattern before fs.suid_dumpable.

[    5.886583] sed (250) used greatest stack depth: 11344 bytes left

cat: /sys/block/mmcblk0p/removable: No such file or directory

[    6.272563] random: crng init done

[    6.272587] random: 7 urandom warning(s) missed due to ratelimiting

[    6.277691] LoadPin: dev(179,22): writable

[    6.293888] LoadPin: load pinning can be disabled.

[    6.293985] LoadPin: kernel-module pinned obj="/lib/modules/4.14.62-07278-g9b007abe7ebc-dirty/kernel/drivers/input/evbug.ko" pid=256 cmdline="udevd --daemon"

[    6.393650] EXT4-fs (mmcblk0p48): recovery complete

[    6.395469] EXT4-fs (mmcblk0p48): mounted filesystem with ordered data mode. Opts: commit=600

/sbin/chromeos_startup: 176: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/block_symlink: Directory nonexistent

/sbin/chromeos_startup: 177: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/block_fifo: Directory nonexistent

[    6.483240] JBD2: no valid journal superblock found

[    6.483271] EXT4-fs (mmcblk0p49): error loading journal

mount: /usr/share/oem: wrong fs type, bad option, bad superblock on /dev/mmcblk0p49, missing codepage or helper program, or other error.

Unable to open FDT property vboot-shared-data

[    6.619811] frecon(311): 

[    6.619830] No monitor available, running headless!

[    6.619860] 

[    6.629383] DEBUG: tsm_screen: 

[    6.629399] new screen

[    6.629430] 

[    6.633846] DEBUG: tsm_vte: 

[    6.633860] new vte object

[    6.638109] 

/sbin/chromeos_startup: 176: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/block_symlink: Directory nonexistent

/sbin/chromeos_startup: 177: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/block_fifo: Directory nonexistent

/sbin/chromeos_startup: 182: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

/sbin/chromeos_startup: 182: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

/sbin/chromeos_startup: 182: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

/sbin/chromeos_startup: 182: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

/sbin/chromeos_startup: 182: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

/sbin/chromeos_startup: 182: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

chmod: changing permissions of '/var/empty': Operation not permitted

[    6.654277] frecon(311): 

[    6.974603] EXT4-fs (mmcblk0p48): re-mounted. Opts: resgid=20119,commit=600,data=ordered

/sbin/chromeos_startup: 177: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_symlink: Directory nonexistent

/sbin/chromeos_startup: 179: /sbin/chromeos_startup: cannot create /sys/kernel/security/chromiumos/inode_security_policies/allow_fifo: Directory nonexistent

[    7.154354] init: ureadahead main process (355) terminated with status 5

[    7.337525] EXT4-fs (mmcblk0p48): re-mounted. Opts: resgid=20119,commit=600,data=ordered

[    8.059835] init: vpd-log main process (379) terminated with status 1

[   67.998535] init: syslog post-start process (479) terminated with status 69

[   68.132131] init: crash-reporter main process (532) killed by ABRT signal

[   69.294676] init: tcsd main process (645) terminated with status 137

[   69.294802] init: tcsd main process ended, respawning

[   69.754632] init: machine-info pre-start process (554) terminated with status 1

[   70.064282] init: qrtr-ns main process (737) killed by ABRT signal

[   73.019151] Failed to initialize the IGMP autojoin socket (err -13)

[   73.670379] Failed to initialize the IGMP autojoin socket (err -13)

[   73.942581] Failed to initialize the IGMP autojoin socket (err -13)

[   74.226324] Failed to initialize the IGMP autojoin socket (err -13)

[   74.393185] Failed to initialize the IGMP autojoin socket (err -13)

[   74.437387] init: ui main process (796) terminated with status 2

[   75.530711] init: machine-info pre-start process (1341) terminated with status 1

[   76.014679] Failed to initialize the IGMP autojoin socket (err -13)

[   76.265803] Failed to initialize the IGMP autojoin socket (err -13)

[   76.408688] Failed to initialize the IGMP autojoin socket (err -13)

[   76.542654] Failed to initialize the IGMP autojoin socket (err -13)

[   76.684682] Failed to initialize the IGMP autojoin socket (err -13)

[   76.723593] init: ui main process (1432) terminated with status 2

[   77.843566] init: machine-info pre-start process (1540) terminated with status 1

[   78.340726] Failed to initialize the IGMP autojoin socket (err -13)

[   78.586813] Failed to initialize the IGMP autojoin socket (err -13)

[   78.729156] Failed to initialize the IGMP autojoin socket (err -13)

[   78.865923] Failed to initialize the IGMP autojoin socket (err -13)

[   79.005741] Failed to initialize the IGMP autojoin socket (err -13)

[   79.045066] init: ui main process (1633) terminated with status 2

[   80.077369] init: machine-info pre-start process (1742) terminated with status 1

[   80.562804] Failed to initialize the IGMP autojoin socket (err -13)

[   80.814304] Failed to initialize the IGMP autojoin socket (err -13)

[   80.960298] Failed to initialize the IGMP autojoin socket (err -13)

[   81.098815] Failed to initialize the IGMP autojoin socket (err -13)

[   81.240227] Failed to initialize the IGMP autojoin socket (err -13)

[   81.279553] init: ui main process (1833) terminated with status 2

[   82.333811] init: machine-info pre-start process (1941) terminated with status 1

[   82.806416] Failed to initialize the IGMP autojoin socket (err -13)

[   83.060274] Failed to initialize the IGMP autojoin socket (err -13)

[   83.199472] Failed to initialize the IGMP autojoin socket (err -13)

[   83.335563] Failed to initialize the IGMP autojoin socket (err -13)

[   83.473255] Failed to initialize the IGMP autojoin socket (err -13)

[   83.510929] init: ui main process (2032) terminated with status 2

[   84.547823] init: machine-info pre-start process (2140) terminated with status 1

[   85.034480] Failed to initialize the IGMP autojoin socket (err -13)

[   85.276183] Failed to initialize the IGMP autojoin socket (err -13)

[   85.417239] Failed to initialize the IGMP autojoin socket (err -13)

[   85.553440] Failed to initialize the IGMP autojoin socket (err -13)

[   85.691215] Failed to initialize the IGMP autojoin socket (err -13)

[   85.728655] init: ui main process (2231) terminated with status 2

[   86.766562] init: machine-info pre-start process (2339) terminated with status 1

[   87.255798] Failed to initialize the IGMP autojoin socket (err -13)

[   87.497303] Failed to initialize the IGMP autojoin socket (err -13)

[   87.637313] Failed to initialize the IGMP autojoin socket (err -13)

[   87.771225] Failed to initialize the IGMP autojoin socket (err -13)

[   87.911929] Failed to initialize the IGMP autojoin socket (err -13)

[   87.949764] init: ui main process (2430) terminated with status 2

[  103.047632] init: Failed to spawn recover_duts main process: unable to execute: No such file or directory

[Mike Frysinger]

i don't think we test booting CrOS w/out the CrOS security LSM.  that's what all those /sys/kernel/security/chromiumos errors are about.

-mike

--

[pva...@codeaurora.org]

I have enabled security LSM. I can see that security related errors are gone now.

But I still see the following ui main process errors which I was concerned about:

[    5.239657] ALSA device lis󙞠  5.254814] EXT4-fs (mmcblk0p22): mounted filesystem without journal. Opts: (null)

[    5.254925] VFS: Mounted root (ext4 filesystem) readonly on device 179:22.

[    5.264498] devtmpfs: mounted

[    5.272987] Freeing unused kernel memory: 2048K

[    5.436124] random: init: uninitialized urandom read (12 bytes read)

[    5.463146] job-filter (217) used greatest stack depth: 11600 bytes left

[    5.561210] mkdir (225) used greatest stack depth: 11456 bytes left

[    5.737468] udevd[235]: starting version 225

[    5.741181] udevd (235) used greatest stack depth: 11264 bytes left

[    5.780343] random: udevd: uninitialized urandom read (16 bytes read)

[    5.783671] random: udevd: uninitialized urandom read (16 bytes read)

[    5.791758] Unsafe core_pattern used with fs.suid_dumpable=2.

[    5.791758] Pipe handler or fully qualified core dump path required.

[    5.791758] Set kernel.core_pattern before fs.suid_dumpable.

sysctl: setting key "kernel.sched_rt_runtime_us": Invalid argument

cat: /sys/block/mmcblk0p/removable: No such file or directory

[    6.233845] EXT4-fs (mmcblk0p48): recovery complete

[    6.235072] EXT4-fs (mmcblk0p48): mounted filesystem with ordered data mode. Opts: commit=600

[    6.279069] random: crng init done

[    6.279093] random: 7 urandom warning(s) missed due to ratelimiting

[    6.347898] JBD2: no valid journal superblock found

[    6.347927] EXT4-fs (mmcblk0p49): error loading journal

mount: /usr/share/oem: wrong fs type, bad option, bad superblock on /dev/mmcblk0p49, missing codepage or helper program, or other error.

Unable to open FDT property vboot-shared-data

[    6.499500] dbus_send_bluto (282) used greatest stack depth: 11200 bytes left

[    6.504836] LoadPin: dev(179,22): writable

[    6.505709] LoadPin: load pinning can be disabled.

[    6.558520] LoadPin: kernel-module pinned obj="/lib/modules/4.14.62-07278-g9b007abe7ebc-dirty/kernel/drivers/input/evbug.ko" pid=259 cmdline="udevd --daemon"

[    6.921952] frecon(319): 

[    6.921970] No monitor available, running headless!

[    6.922000] 

[    6.931648] DEBUG: tsm_screen: 

[    6.931663] new screen

[    6.931694] 

[    6.936147] DEBUG: tsm_vte: 

[    6.936163] new vte object

[    6.937707] 

chmod: changing permissions of '/var/empty': Operation not permitted

[    6.958311] frecon(319): 

[    7.146752] EXT4-fs (mmcblk0p48): re-mounted. Opts: resgid=20119,commit=600,data=ordered

[    7.477669] EXT4-fs (mmcblk0p48): re-mounted. Opts: resgid=20119,commit=600,data=ordered

[    8.187985] init: crash-reporter main process (474) killed by ABRT signal

[    8.217462] init: vpd-log main process (376) terminated with status 1

[    9.602381] init: tcsd main process (636) terminated with status 137

[    9.602508] init: tcsd main process ended, respawning

[   10.185694] init: machine-info pre-start process (548) terminated with status 1

[   12.424230] init: rmtfs main process (1010) killed by ABRT signal

[   12.989893] Failed to initialize the IGMP autojoin socket (err -13)

[   13.781442] Failed to initialize the IGMP autojoin socket (err -13)

[   14.290208] Failed to initialize the IGMP autojoin socket (err -13)

[   14.555479] Failed to initialize the IGMP autojoin socket (err -13)

[   14.827098] Failed to initialize the IGMP autojoin socket (err -13)

[   14.865286] init: ui main process (715) terminated with status 2

[   15.717170] init: machine-info pre-start process (1310) terminated with status 1

[   16.151549] Failed to initialize the IGMP autojoin socket (err -13)

[   16.391893] Failed to initialize the IGMP autojoin socket (err -13)

[   16.526785] Failed to initialize the IGMP autojoin socket (err -13)

[   16.665575] Failed to initialize the IGMP autojoin socket (err -13)

[   16.799672] Failed to initialize the IGMP autojoin socket (err -13)

[   16.833344] init: ui main process (1394) terminated with status 2

[   17.683389] init: machine-info pre-start process (1485) terminated with status 1

[   18.143260] Failed to initialize the IGMP autojoin socket (err -13)

[   18.445406] Failed to initialize the IGMP autojoin socket (err -13)

[   18.581739] Failed to initialize the IGMP autojoin socket (err -13)

[   18.719884] Failed to initialize the IGMP autojoin socket (err -13)

[   18.854992] Failed to initialize the IGMP autojoin socket (err -13)

[   18.890626] init: ui main process (1569) terminated with status 2

[   19.737175] init: machine-info pre-start process (1663) terminated with status 1

[   20.167989] Failed to initialize the IGMP autojoin socket (err -13)

[   20.413217] Failed to initialize the IGMP autojoin socket (err -13)

[   20.546539] Failed to initialize the IGMP autojoin socket (err -13)

[   20.687661] Failed to initialize the IGMP autojoin socket (err -13)

[   20.819307] Failed to initialize the IGMP autojoin socket (err -13)

[   20.856901] init: ui main process (1747) terminated with status 2

[   21.704485] init: machine-info pre-start process (1838) terminated with status 1

[   22.163257] Failed to initialize the IGMP autojoin socket (err -13)

[   22.395888] Failed to initialize the IGMP autojoin socket (err -13)

[   22.525155] Failed to initialize the IGMP autojoin socket (err -13)

[   22.662823] Failed to initialize the IGMP autojoin socket (err -13)

[   22.792334] Failed to initialize the IGMP autojoin socket (err -13)

[   22.827806] init: ui main process (1922) terminated with status 2

[   23.662472] init: machine-info pre-start process (2013) terminated with status 1

[   24.079403] Failed to initialize the IGMP autojoin socket (err -13)

[   24.321548] Failed to initialize the IGMP autojoin socket (err -13)

[   24.458372] Failed to initialize the IGMP autojoin socket (err -13)

[   24.592686] Failed to initialize the IGMP autojoin socket (err -13)

[   24.727002] Failed to initialize the IGMP autojoin socket (err -13)

[   24.760883] init: ui main process (2097) terminated with status 2

[   25.586727] init: machine-info pre-start process (2188) terminated with status 1

[   26.012990] Failed to initialize the IGMP autojoin socket (err -13)

[   26.255735] Failed to initialize the IGMP autojoin socket (err -13)

[   26.392363] Failed to initialize the IGMP autojoin socket (err -13)

[   26.524823] Failed to initialize the IGMP autojoin socket (err -13)

[   26.661903] Failed to initialize the IGMP autojoin socket (err -13)

[   26.695997] init: ui main process (2272) terminated with status 2

[Doug Anderson]

Hi,

On Fri, Sep 14, 2018 at 4:37 AM, <pva...@codeaurora.org> wrote:

I have enabled security LSM. I can see that security related errors are gone now.

But I still see the following ui main process errors which I was concerned about:

If your graphics aren't coming up then that will cause UI to crash like this.  Presumably you're either lacking some patches to enable graphics or lacking some sort of config.  

If you've got a test image you ought to be able to ssh to the device to get further logs now.  ...or you can enable an agetty on the serial port and just login from there.  Maybe you could look at various chrome / ui logs in "/var/log".

-Doug

[pva...@codeaurora.org]

Is there a way to disable login screen and get login prompt from serial port?

[Doug Anderson]

It's usually not that important to disable the login screen.  Just let UI crash and ignore it.  

...for getting login prompt from serial port, take a look at the "TTY_CONSOLE" setting in the "profiles/base/make.defaults" of the overlay you're using (or perhaps the baseboard).  That should be set to the port you want the agetty on.  That's used in the "chromeos-base/tty/tty-0.0.1.ebuild" ebuild in chromium-os-overlay.

In order for that to take effect you need your device to report as being in debug mode.  One of the easier ways to do this is to make sure cros_debug is in your kernel command line arguments.

-Doug

[pva...@codeaurora.org]

TTY_CONSOLE is configured properly(ttyMSM0 in my case).

What does the following two errors mean? Am I missing anything from kernel perspective?

[    6.310052] init: ureadahead main process (379) terminated with status 5

[    6.583588] init: syslog main process (503) killed by ABRT signal

[    6.583740] init: syslog main process ended, respawning

[Mike Frysinger]

this is the point where you get to debug these failures yourself.  for each failing init script, look at the script itself, and then try running the program by hand.  if it fails, debug it.

-mike

[pva...@codeaurora.org]

Yes Mike, I am trying to debug... but the problem is that I didn't entered into the shell yet... 

I am only getting the logs from serial port. Do I have any other alternate to debug application process failures?

Thanks,

Prashanth

[Doug Anderson]

Did you confirm "cros_debug" is in your kernel command line?  I'm guessing that's why your serial console isn't coming up...  You could also hack:

  /etc/init/console-tty*.conf

...in your root filesystem to not check and just always open the agetty.

-Doug

[pva...@codeaurora.org]

Yes, my kernel cmd_line has cros_debug option.

fastboot -c "noinitrd init=/sbin/init root=/dev/mmcblk0p22 ro rootwait debug loglevel=7 console=ttyMSM0,115200,n8 cros_debug pd_ignore_unused" boot boot.img

Also console tty conf looks fine to me:

start on started boot-services

stop on stopping boot-services

respawn

env TTY_BAUD_RATE=115200

# This file is generated at build time by chromeos-base/tty.

script

  if crossystem "cros_debug?1"; then

    exec agetty "${TTY_BAUD_RATE}" ttyMSM0 linux

  else

    stop

    exit 0

  fi

end script

[Doug Anderson]

Hi,

Can you hack it to take the "if crossystem "cros_debug?1"" bit out?  AKA, just:

---

script

  exec agetty "${TTY_BAUD_RATE}" ttyMSM0 linux

end script

---

You could also try changing the "start on" to start this earlier in the boot process.

-Doug

---

[Mike Frysinger]

s/started boot-services/starting boot-services/

or have it start even earlier in the boot process

you should focus on getting a root shell first before trying to figure out why random services are failing.  once you have that root shell, you can debug why the services are failing.

-mike

[pva...@codeaurora.org]

Thx Mike and Douglas... Now I am able to enter into the shell...

Thanks

Prashanth