Boot on Raspberry Pi ends prematurely when accessing ramdisk

[Jakub Jermář]

As of current master, the boot on Raspberry Pi ends prematurely as follows. Seems like it cannot access files on the ramdisk. This happens both during a u-boot boot and a direct boot from the SD card.

U-Boot> loady
## Ready for binary (ymodem) download to 0x00200000 at 115200 bps...                                                                                          
CCX)/0(CAN) packets, 29 retries
## Total Size      = 0x001a2d78 = 1715576 Bytes
U-Boot> bootm
## Booting kernel from Legacy Image at 00200000 ...
   Image Name:   HelenOS-0.9.1
   Image Type:   ARM Linux Kernel Image (uncompressed)
   Data Size:    1715512 Bytes = 1.6 MiB
   Load Address: 00008000
   Entry Point:  00008000
   Verifying Checksum ... OK
   Loading Kernel Image ... OK

Starting kernel ...

HelenOS bootloader, release 0.9.1 (Armonia), revision b27553c1c
Built on 2021-03-22 17:56:58 for arm32
Copyright (c) 2001-2019 HelenOS project
Boot loader: 0x00008000 -> 0x00015d38

Memory statistics
 0x00015000|0x00015000: bootstrap stack
 0x00010000|0x00010000: bootstrap page table
 0x00015830|0x00015830: boot info structure
 0x80a08000|0x00a08000: kernel entry point
Boot loader: 0x00008000 -> 0x00015d38
Payload: 0x00015d38 -> 0x001aad38
Kernel load address: 0x00a08000
Kernel start: 0x80a08000
RAM end: 0x01a08000 (16777216 bytes available)

Inflating components ... 
 0x80a08000|0x00a08000: kernel.elf.gz image (494232/148931 bytes)
 0x80a81000|0x00a81000: ns.gz image (110780/51462 bytes)
 0x80a9d000|0x00a9d000: loader.gz image (117256/54739 bytes)
 0x80aba000|0x00aba000: init.gz image (139776/64299 bytes)
 0x80add000|0x00add000: locsrv.gz image (125980/59087 bytes)
 0x80afc000|0x00afc000: rd.gz image (117128/54449 bytes)
 0x80b19000|0x00b19000: vfs.gz image (141556/65105 bytes)
 0x80b3c000|0x00b3c000: logger.gz image (123456/57180 bytes)
 0x80b5b000|0x00b5b000: fat.gz image (187236/87807 bytes)
 0x80b89000|0x00b89000: initrd.img.gz image (4024832/999618 bytes)
Done.
Booting the kernel...
SPARTAN kernel, release 0.9.1 (Armonia), revision b27553c1c
Built on 2021-03-22 17:56:58 for arm32
Copyright (c) 2001-2019 HelenOS project
Detected 1 CPU(s), 196576 KiB free memory
Program loader at 0xc0020000
Kernel console ready (press any key to activate)
RAM disk at 0x00b89000 (size 4024832 bytes)
[init:ns(2)] ns: HelenOS IPC Naming Service
[init:ns(2)] ns: Accepting connections
[init:init(3)] init: HelenOS init
[init:locsrv(4)] loc: HelenOS Location Service
[init:rd(5)] rd: HelenOS RAM disk server
[init:rd(5)] rd: Found RAM disk at 0x00b89000, 4024832 bytes
[init:vfs(6)] vfs: HelenOS VFS server
[init:logger(7)] logger: HelenOS Logging Service
[init:fat(8)] fat: HelenOS FAT file system server
[init:logger(7)] logger: Accepting connections
[init:locsrv(4)] loc: Accepting connections
[init:rd(5)] rd: Accepting connections
[init:vfs(6)] vfs: Accepting connections
[init:fat(8)] fat: Accepting connections
[init:init(3)] init: Root file system mounted on / (fat at bd/initrd)
[init:init(3)] init: Unable to stat /srv/fs/tmpfs
[init:init(3)] init: Unable to stat /srv/fs/exfat
[init:init(3)] init: Unable to stat /srv/fs/cdfs
[init:init(3)] init: Unable to stat /srv/fs/mfs
[init:init(3)] init: Starting /srv/klog
[init:init(3)] init: Error spawning /srv/klog ([EINVAL] Invalid value)
[init:init(3)] init: Starting /srv/fs/locfs
[init:init(3)] init: Error spawning /srv/fs/locfs ([EINVAL] Invalid value)
[init:init(3)] init: Unable to stat /srv/taskmon

[Jakub Jermář]

It turns out that his problem shows already with 0.9.1 when built with the current toolchain (but not in the released 0.9.1). On the current master the problem goes away for a static build. With RTLD_DEBUG enabled, I get the following boot:

HelenOS bootloader, release 0.9.1 (Armonia), revision b27553c1c
Built on 2021-03-22 22:17:30 for arm32
Copyright (c) 2001-2019 HelenOS project
Boot loader: 0x00008000 -> 0x00015d38

Memory statistics
 0x00015000|0x00015000: bootstrap stack
 0x00010000|0x00010000: bootstrap page table
 0x00015830|0x00015830: boot info structure
 0x80a08000|0x00a08000: kernel entry point
Boot loader: 0x00008000 -> 0x00015d38
Payload: 0x00015d38 -> 0x0016ed38
Kernel load address: 0x00a08000
Kernel start: 0x80a08000
RAM end: 0x01a08000 (16777216 bytes available)

Inflating components ... 
 0x80a08000|0x00a08000: kernel.elf.gz image (415344/122432 bytes)
 0x80a6e000|0x00a6e000: ns.gz image (77528/39458 bytes)
 0x80a81000|0x00a81000: loader.gz image (84992/43473 bytes)
 0x80a96000|0x00a96000: init.gz image (102604/51212 bytes)
 0x80ab0000|0x00ab0000: locsrv.gz image (91936/46979 bytes)
 0x80ac7000|0x00ac7000: rd.gz image (83752/42527 bytes)
 0x80adc000|0x00adc000: vfs.gz image (103600/51794 bytes)
 0x80af6000|0x00af6000: logger.gz image (89224/45052 bytes)
 0x80b0c000|0x00b0c000: fat.gz image (145984/73230 bytes)
 0x80b30000|0x00b30000: initrd.img.gz image (3661312/887287 bytes)
Done.
Booting the kernel...
SPARTAN kernel, release 0.9.1 (Armonia), revision b27553c1c
Built on 2021-03-22 22:17:30 for arm32
Copyright (c) 2001-2019 HelenOS project
Detected 1 CPU(s), 458720 KiB free memory
Program loader at 0xc0017000
RAM disk at 0x00b30000 (size 3661312 bytes)
Kernel console ready (press any key to activate)
[init:ns(2)] ns: HelenOS IPC Naming Service
[init:ns(2)] ns: Accepting connections
[init:init(3)] init: HelenOS init
[init:locsrv(4)] loc: HelenOS Location Service
[init:rd(5)] rd: HelenOS RAM disk server
[init:rd(5)] rd: Found RAM disk at 0x00b30000, 3661312 bytes
[init:vfs(6)] vfs: HelenOS VFS server
[init:logger(7)] logger: HelenOS Logging Service
[init:fat(8)] fat: HelenOS FAT file system server
[init:logger(7)] logger: Accepting connections
[init:locsrv(4)] loc: Accepting connections
[init:vfs(6)] vfs: Accepting connections
[init:rd(5)] rd: Accepting connections
[init:fat(8)] fat: Accepting connections
[init:init(3)] init: Root file system mounted on / (fat at bd/initrd)
[init:init(3)] init: Unable to stat /srv/fs/tmpfs
[init:init(3)] init: Unable to stat /srv/fs/exfat
[init:init(3)] init: Unable to stat /srv/fs/cdfs
[init:init(3)] init: Unable to stat /srv/fs/mfs
[init:init(3)] init: Starting /srv/klog
[loader(9)] Load dynamically linked program.
[loader(9)] Parse program .dynamic section at 0x00101b24
[loader(9)] memset
[loader(9)] pass 1
[loader(9)] tag=1 ptr=0x1 val=1
[loader(9)] tag=15 ptr=0x143 val=323
[loader(9)] tag=4 ptr=0x100094 val=1048724
[loader(9)] tag=5 ptr=0x1002d4 val=1049300
[loader(9)] tag=6 ptr=0x100144 val=1048900
[loader(9)] tag=10 ptr=0x14f val=335
[loader(9)] tag=11 ptr=0x10 val=16
[loader(9)] tag=21 ptr=0x0 val=0
[loader(9)] tag=3 ptr=0x101bcc val=1055692
[loader(9)] tag=2 ptr=0xa8 val=168
[loader(9)] tag=20 ptr=0x11 val=17
[loader(9)] tag=23 ptr=0x10043c val=1049660
[loader(9)] tag=17 ptr=0x100424 val=1049636
[loader(9)] tag=18 ptr=0x18 val=24
[loader(9)] tag=19 ptr=0x8 val=8
[loader(9)] str_tab=0x1002d4, soname_idx=0x0, soname=0x1002d4
[loader(9)] soname=''
[loader(9)] rpath='$ORIGIN/lib'
[loader(9)] hash=0x100094
[loader(9)] dt_rela=0x0
[loader(9)] dt_rela_sz=0x0
[loader(9)] dt_rel=0x100424
[loader(9)] dt_rel_sz=0x18
[loader(9)] pass 2
[loader(9)] needed:'libc.so.0'
[loader(9)] prog tdata at 0x00000000 size 0, tbss size 0
[loader(9)] Load all program dependencies
[loader(9)] module_load_deps('[program]')
[loader(9)] [program] needs libc.so.0
[loader(9)] module_find('libc.so.0')
[loader(9)] m = 0x70134140
[loader(9)] filename:'/lib/libc.so.0'
[loader(9)] Failed to load '/lib/libc.so.0'
[init:init(3)] init: Error spawning /srv/klog ([EINVAL] Invalid value)
[init:init(3)] init: Starting /srv/fs/locfs
[loader(10)] Load dynamically linked program.
[loader(10)] Parse program .dynamic section at 0x00103f8c
[loader(10)] memset
[loader(10)] pass 1
[loader(10)] tag=1 ptr=0x1 val=1
[loader(10)] tag=15 ptr=0x3a9 val=937
[loader(10)] tag=4 ptr=0x100094 val=1048724
[loader(10)] tag=5 ptr=0x1005a4 val=1050020
[loader(10)] tag=6 ptr=0x100214 val=1049108
[loader(10)] tag=10 ptr=0x3b5 val=949
[loader(10)] tag=11 ptr=0x10 val=16
[loader(10)] tag=21 ptr=0x0 val=0
[loader(10)] tag=3 ptr=0x104034 val=1065012
[loader(10)] tag=2 ptr=0x1b0 val=432
[loader(10)] tag=20 ptr=0x11 val=17
[loader(10)] tag=23 ptr=0x10096c val=1050988
[loader(10)] tag=17 ptr=0x10095c val=1050972
[loader(10)] tag=18 ptr=0x10 val=16
[loader(10)] tag=19 ptr=0x8 val=8
[loader(10)] str_tab=0x1005a4, soname_idx=0x0, soname=0x1005a4
[loader(10)] soname=''
[loader(10)] rpath='$ORIGIN/lib'
[loader(10)] hash=0x100094
[loader(10)] dt_rela=0x0
[loader(10)] dt_rela_sz=0x0
[loader(10)] dt_rel=0x10095c
[loader(10)] dt_rel_sz=0x10
[loader(10)] pass 2
[loader(10)] needed:'libc.so.0'
[loader(10)] prog tdata at 0x00000000 size 0, tbss size 0
[loader(10)] Load all program dependencies
[loader(10)] module_load_deps('[program]')
[loader(10)] [program] needs libc.so.0
[loader(10)] module_find('libc.so.0')
[loader(10)] m = 0x70134140
[loader(10)] filename:'/lib/libc.so.0'
[loader(10)] Failed to load '/lib/libc.so.0'
[init:init(3)] init: Error spawning /srv/fs/locfs ([EINVAL] Invalid value)
[init:init(3)] init: Unable to stat /srv/taskmon

[Jiri Svoboda]

I cannot reproduce the issue (in Qemu with latest ew.py) despite rebuilding the OS with the latest toolchain freshly built with toolchain.sh arm32:

[jirka@omelette build-rpi]$ /usr/local/cross/bin/arm-helenos-ld --version
GNU ld (GNU Binutils) 2.31.1
Copyright (C) 2018 Free Software Foundation, Inc.
This program is free software; you may redistribute it under the terms of
the GNU General Public License version 3 or (at your option) a later version.
This program has absolutely no warranty.
[jirka@omelette build-rpi]$ /usr/local/cross/bin/arm-helenos-gcc --version
arm-helenos-gcc (GCC) 8.2.0
Copyright (C) 2018 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

[Jakub Jermář]

Turns out that with python3, the tools/mkfat.py script builds initrd.img which is missing several subdirectories, including app/ and lib/. This makes the boot process not find /lib/libc.so.0 and manifests as this bug.

It is not clear why it only happens with the Raspberry Pi config though.

[Jakub Jermář]

The problem seems to originate in the mkfat.py script, which misbehaves with Python3.

More specifically, in function fat_lchar I had to apply the following path in order to get a correct image:

diff --git a/tools/mkfat.py b/tools/mkfat.py
index 0e519b192..ad3647558 100755
--- a/tools/mkfat.py
+++ b/tools/mkfat.py
@@ -192,8 +192,8 @@ def fat_lchars(name):
        filtered = False
 
        for char in name.encode('ascii', 'replace').upper():
-               if char in lchars:
-                       filtered_name += char
+               if chr(char) in lchars:
+                       filtered_name += str.encode(chr(char))
                else:
                        filtered_name += b'_'
                        filtered = True

Without the patch, name would be always thought of as containing invalid characters and thus a LFN would be created in all cases. This somehow results in the initrd.img being incorrect.

[Jakub Jermář]

Fixed in commit ​fbc6b6c900ca1732db75de47e7c7148158ce3ac6