haiku_loader doesn't launch bash, it stops before prompt

[kenz-gelsoft]

Hello, I wanna try this but it cannot launch Haiku's bash. It gets stucked here.

[kenz@archlinux bin]$ ./haiku_loader bash --login
Attempting to launch HyClone server...
HyClone owner UID: 1000
HyClone owner GID: 1000
Preinstalled package: "graphite2-1.3.14-2-x86_64.hpkg"
Preinstalled package: "gcc_syslibs-13.2.0_2023_08_10-3-x86_64.hpkg"
Preinstalled package: "bash-5.2.015-1-x86_64.hpkg"
Preinstalled package: "openssl-1.1.1w-1-x86_64.hpkg"
Preinstalled package: "zlib-1.2.13-2-x86_64.hpkg"
Preinstalled package: "ncurses6-6.3-2-x86_64.hpkg"
Preinstalled package: "libpng16-1.6.40-1-x86_64.hpkg"
Preinstalled package: "gettext_libintl-0.21.1-4-x86_64.hpkg"
Preinstalled package: "libxml2-2.10.4-3-x86_64.hpkg"
Preinstalled package: "gawk-5.2.2-1-x86_64.hpkg"
Preinstalled package: "haiku-r1~beta4_hrev57357-1-x86_64.hpkg"
Preinstalled package: "bzip2-1.0.8-3-x86_64.hpkg"
Preinstalled package: "harfbuzz-8.2.1-1-x86_64.hpkg"
Preinstalled package: "noto-20200106-1-x86_64.hpkg"
Preinstalled package: "expat-2.5.0-2-x86_64.hpkg"
Preinstalled package: "ralink_wifi_firmwares-2015_02_11-2-x86_64.hpkg"
Preinstalled package: "realtek_wifi_firmwares-2019_01_02-1-x86_64.hpkg"
Preinstalled package: "noto_sans_cjk_jp-1.004-2-x86_64.hpkg"
Preinstalled package: "libsolv-0.3.0_haiku_2014_12_22-5-x86_64.hpkg"
Preinstalled package: "libedit-20210910_3.1-3-x86_64.hpkg"
Preinstalled package: "gzip-1.12-1-x86_64.hpkg"
Preinstalled package: "zstd-1.5.5-1-x86_64.hpkg"
Preinstalled package: "readline-8.2.001-1-x86_64.hpkg"
Preinstalled package: "coreutils-9.3-3-x86_64.hpkg"
Preinstalled package: "freetype-2.12.1-4-x86_64.hpkg"
Preinstalled package: "tar-1.35-2-x86_64.hpkg"
Preinstalled package: "icu66-66.1-3-x86_64.hpkg"
Preinstalled package: "unzip-6.10c23-5-x86_64.hpkg"
Preinstalled package: "fontconfig-2.13.96-2-x86_64.hpkg"
Preinstalled package: "intel_wifi_firmwares-2023_03_06-1-x86_64.hpkg"
Preinstalled package: "ca_root_certificates-2022_10_11-1-x86_64.hpkg"
Preinstalled package: "libiconv-1.17-3-x86_64.hpkg"
Keeping installed package: ca_root_certificates-2022_10_11-1-x86_64.hpkg
Keeping installed package: gettext_libintl-0.21.1-4-x86_64.hpkg
Keeping installed package: zlib-1.2.13-2-x86_64.hpkg
Keeping installed package: bzip2-1.0.8-3-x86_64.hpkg
Keeping installed package: haiku-r1~beta4_hrev57357-1-x86_64.hpkg
Keeping installed package: harfbuzz-8.2.1-1-x86_64.hpkg
Keeping installed package: libpng16-1.6.40-1-x86_64.hpkg
Keeping installed package: expat-2.5.0-2-x86_64.hpkg
Keeping installed package: noto_sans_cjk_jp-1.004-2-x86_64.hpkg
Keeping installed package: gzip-1.12-1-x86_64.hpkg
Keeping installed package: intel_wifi_firmwares-2023_03_06-1-x86_64.hpkg
Keeping installed package: ncurses6-6.3-2-x86_64.hpkg
Keeping installed package: icu66-66.1-3-x86_64.hpkg
Keeping installed package: openssl-1.1.1w-1-x86_64.hpkg
Keeping installed package: libiconv-1.17-3-x86_64.hpkg
Keeping installed package: gawk-5.2.2-1-x86_64.hpkg
Keeping installed package: noto-20200106-1-x86_64.hpkg
Keeping installed package: libxml2-2.10.4-3-x86_64.hpkg
Keeping installed package: gcc_syslibs-13.2.0_2023_08_10-3-x86_64.hpkg
Keeping installed package: libsolv-0.3.0_haiku_2014_12_22-5-x86_64.hpkg
Keeping installed package: libedit-20210910_3.1-3-x86_64.hpkg
Keeping installed package: coreutils-9.3-3-x86_64.hpkg
Keeping installed package: zstd-1.5.5-1-x86_64.hpkg
Keeping installed package: readline-8.2.001-1-x86_64.hpkg
Keeping installed package: ralink_wifi_firmwares-2015_02_11-2-x86_64.hpkg
Keeping installed package: freetype-2.12.1-4-x86_64.hpkg
Keeping installed package: bash-5.2.015-1-x86_64.hpkg
Keeping installed package: graphite2-1.3.14-2-x86_64.hpkg
Keeping installed package: tar-1.35-2-x86_64.hpkg
Keeping installed package: realtek_wifi_firmwares-2019_01_02-1-x86_64.hpkg
Keeping installed package: unzip-6.10c23-5-x86_64.hpkg
Keeping installed package: fontconfig-2.13.96-2-x86_64.hpkg
Done extracting packagefs at "/boot/system"
Done extracting packagefs at "/boot/home/config"
HyClone server listening on /home/kenz/.hprefix
Starting launch_daemon

Switching to architecture x86_64

loader_load_runtime: failed to register runtime_loader image: -2147483643
loader_load_runtime: failed to register runtime_loader image: -2147483643
loader_load_runtime: failed to register runtime_loader image: -2147483643

uname -a

Linux archlinux 6.5.9-arch2-1 #1 SMP PREEMPT_DYNAMIC Thu, 26 Oct 2023 00:52:20 +0000 x86_64 GNU/Linux

hyclone's revision

f590514

[trungnt2910]

-2147483643 is 0x80000005, which translates to B_BAD_VALUE.

This occurs in a hserver call:

    status_t status = loader_hserver_call_register_image(&haiku_info, sizeof(haiku_info));
    if (status < 0)
    {
        std::cerr << "loader_load_runtime: failed to register runtime_loader image: " << status << std::endl;
        return false;
    }

It should be somewhere here:

intptr_t server_hserver_call_register_image(hserver_context& context, void* image_info, std::size_t size)
{
    if (size != sizeof(haiku_extended_image_info))
    {
        return B_BAD_VALUE;
    }

Seems like image_info has been updated upstream since the last time I've touched hyclone.

However, a quick browse of the source does not indicate so.

Can you somehow debug hyclone_server (using gdb running as root) and get the size parameter? Alternatively, you can insert a std::cerr statement there and then tail -f $HPREFIX/.hyclone.log.

[kenz-gelsoft]

Thank you for taking this. I added logging:

[kenz@archlinux hyclone]$ git diff
diff --git a/hyclone_server/image.cpp b/hyclone_server/image.cpp
index 720ca27..4af066f 100644
--- a/hyclone_server/image.cpp
+++ b/hyclone_server/image.cpp
@@ -13,6 +13,7 @@ intptr_t server_hserver_call_register_image(hserver_context& context, void* imag
 {
     if (size != sizeof(haiku_extended_image_info))
     {
+        std::cerr << "server_hserver_call_register_image: size=" << size << std::endl;
         return B_BAD_VALUE;
     }
 

but log doesn't contain added logging.

[kenz@archlinux hyclone]$ grep size $HPREFIX/.hyclone.log
[kenz@archlinux hyclone]$ 

so I guess context.process->RegisterImage() returns B_BAD_VALUE.

[kenz-gelsoft]

By moving logging to outside of if clause

[kenz@archlinux hyclone]$ git diff
diff --git a/hyclone_server/image.cpp b/hyclone_server/image.cpp
index 720ca27..d554327 100644
--- a/hyclone_server/image.cpp
+++ b/hyclone_server/image.cpp
@@ -11,6 +11,7 @@
 
 intptr_t server_hserver_call_register_image(hserver_context& context, void* image_info, std::size_t size)
 {
+    std::cerr << "server_hserver_call_register_image: size=" << size << std::endl;
     if (size != sizeof(haiku_extended_image_info))
     {
         return B_BAD_VALUE;

it logs size=1136 multiple times, so above logging should works correctly.

[kenz@archlinux hyclone]$ grep size $HPREFIX/.hyclone.log | uniq
server_hserver_call_register_image: size=1136
[kenz@archlinux hyclone]$ 

I will try debugging maybe this weekend.

[trungnt2910]

Under normal circumstances this should not happen:

int Process::RegisterImage(const haiku_extended_image_info& image)
{
    int id = _images.Add(image);
    _images.Get(id).basic_info.id = id;
    _info.image_count = _images.size();
    return id;
}

By moving logging to outside of if clause

Maybe logging sizeof(haiku_extended_image_info) might help. If it's not 1136, you might want to try to get the real struct extended_image_info on Haiku and see which HyClone component(s) is getting the size wrong.

[kenz-gelsoft]

Under normal circumstances this should not happen:

Indeed.

Maybe logging sizeof(haiku_extended_image_info) might help. If it's not 1136, you might want to try to get the real struct extended_image_info on Haiku and see which HyClone component(s) is getting the size wrong.

It didn't help. logging sizeof(haiku_extended_image_info) is always 1136.

I will try debugging maybe this weekend.

So I tried debugging, but debug build works correctly... Some optimization may be the cause.

• Changed CMAKE_BUILD_TYPE to Debug with ccmake ...
• sudo make install again
• With lldb, it works correctly.
• Without debugging, problem doesn't occur.

[trungnt2910]

Which compiler and optimization flags are you using?

Normally I do test release builds, but there may have been some undefined behavior somewhere that only arises in certain modes of certain compilers.

[kenz-gelsoft]

gcc version

c++ --version
c++ (GCC) 13.2.1 20230801
Copyright (C) 2023 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.

I don't specify any special optimization flags (arch linux g++ default)

I'm testing some CMake optimization options

• NG:
  • (None) - default
  • Release
  • MinSizeRel - needs disabling -Werror
• OK
  • Debug

Will try clang++ tonight. And maybe RelWithDebugInfo could be used to debug.

[trungnt2910]

Also, it might be the case that the servercall hasn't even reached the function yet - B_BAD_VALUE is returned from the dispatcher:

hyclone/hyclone_server/server_dispatch.cpp

Lines 35 to 56 in f590514

	// For SERVERCALL_ID_connect, the process and thread hasn't been registered
	// in HyClone server yet.
	if (call_id != SERVERCALL_ID_connect)
	{
	context.process = system.GetProcess(context.pid).lock();
	if (!context.process)
	{
	return B_BAD_VALUE;
	}
	}
	}
	if (context.process)
	{
	auto procLock = context.process->Lock();
	context.thread = context.process->GetThread(context.tid).lock();
	if (!context.thread)
	{
	return B_BAD_VALUE;
	}
	}

Considering what you said in #15 (comment) and #15 (comment), this might be the problem. For calls that pass through the dispatcher, server_hserver_call_register_image always succeeds, but for those that don't, the function isn't called at all.

Before any further debugging I suggest adding logs to the if (!context.process) blocks in server_dispatch.cpp.

[kenz-gelsoft]

Before any further debugging I suggest adding logs to the if (!context.process) blocks in server_dispatch.cpp.

if (!context.process) block logged returning B_BAD_VALUE.

diff --git a/hyclone_server/server_dispatch.cpp b/hyclone_server/server_dispatch.cp
p
index 1e534b8..c17c456 100644
--- a/hyclone_server/server_dispatch.cpp
+++ b/hyclone_server/server_dispatch.cpp
@@ -1,4 +1,5 @@
 #include <cstddef>
+#include <iostream>
 #include "haiku_errors.h"
 #include "process.h"
 #include "servercalls.h"
@@ -39,6 +40,7 @@ intptr_t server_dispatch(intptr_t conn_id, intptr_t call_id,
             context.process = system.GetProcess(context.pid).lock();
             if (!context.process)
             {
+                std::cerr << "!context.process" << std::endl;
                 return B_BAD_VALUE;
             }
         }
@@ -51,6 +53,7 @@ intptr_t server_dispatch(intptr_t conn_id, intptr_t call_id,
 
         if (!context.thread)
         {
+            std::cerr << "!context.thread" << std::endl;
             return B_BAD_VALUE;
         }
     }

[kenz@archlinux ~]$ grep \! $HPREFIX/.hyclone.log 
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
3 5 6 18 9 23 19 12 13 24 15 16 17 14 8 20 !context.process21 22 
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process
!context.process

[kenz-gelsoft]

I added pid/tid to log, it tells pid=-1. I should have uploaded entire log.

(This time, it doesn't stop before prompt w/ RelWithDebInfo build.)

_hyclone.log

[kenz-gelsoft]

While debugging I saw connect() to server socket fails in ServerConnection::Connect(false)

hyclone/haiku_loader/sys/linux/loader_servercalls.cpp

Lines 74 to 81 in f590514

	int ret = connect(_socket, (const struct sockaddr *)&_addr,
	sizeof(struct sockaddr_un));
	if (ret == -1)
	{
	close(_socket);
	_socket = -1;
	return false;
	}

* thread #1, name = 'haiku_loader', stop reason = step over
  * frame #0: 0x00005555555725c0 haiku_loader`ServerConnection::Connect(this=0x00007ffff7e8f98c, forceReconnect=<unavailable>) at loader_servercalls.cpp:113:10
    frame #1: 0x000055555555d8a5 haiku_loader`main at main.cpp:335:30
    frame #2: 0x00007ffff7a45cd0 libc.so.6`___lldb_unnamed_symbol3187 + 128
    frame #3: 0x00007ffff7a45d8a libc.so.6`__libc_start_main + 138
    frame #4: 0x000055555555e845 haiku_loader`_start + 37

Though RelWithDebInfo reports inlined and optimized callstack, this is call from:

• hyclone/haiku_loader/sys/linux/loader_servercalls.cpp

  Line 293 in f590514

  if (!gServerConnection.Connect())

• hyclone/haiku_loader/main.cpp

  Line 335 in f590514

  if (!loader_init_servercalls())

.hyclone.log is:

• _hyclone.log

[kenz-gelsoft]

My laptop encountering this is very poor spec.

• CPU: Intel® Celeron® N4500 × 2
  • just two core!
• RAM: 4.0 GiB

I guess hyclone_loader forks hyclone_server and hyclone_loader assumes hyclone_server is ready to listen when waitpid() succeeds, but hyclone_server didn't finish setting up the socket at that time.

hyclone/haiku_loader/sys/linux/loader_servercalls.cpp

Lines 286 to 296 in f590514

	if (waitpid(pid, NULL, 0) == -1)
	{
	return false;
	}
	// Here, the server should have daemonized and is listening to the socket.
	if (!gServerConnection.Connect())
	{
	return false;
	}

[kenz-gelsoft]

Inserting 5sec sleep to above code,

diff --git a/haiku_loader/sys/linux/loader_servercalls.cpp b/haiku_loader/sys/linux/loader_servercalls.cpp
index 9ff8e5c..30c55e5 100644
--- a/haiku_loader/sys/linux/loader_servercalls.cpp
+++ b/haiku_loader/sys/linux/loader_servercalls.cpp
@@ -288,6 +288,9 @@ bool loader_init_servercalls()
         return false;
     }
 
+    // Waiting 5secs for server setup.
+    sleep(5);
+
     // Here, the server should have daemonized and is listening to the socket.
 
     if (!gServerConnection.Connect())

but it doesn't workaround stop before prompt (it never prompt me).

Keeping installed package: bash-5.2.015-1-x86_64.hpkg
Keeping installed package: graphite2-1.3.14-2-x86_64.hpkg
Keeping installed package: tar-1.35-2-x86_64.hpkg
Keeping installed package: realtek_wifi_firmwares-2019_01_02-1-x86_64.hpkg
Keeping installed package: unzip-6.10c23-5-x86_64.hpkg
Keeping installed package: fontconfig-2.13.96-2-x86_64.hpkg
Done extracting packagefs at "/boot/system"
Done extracting packagefs at "/boot/home/config"
HyClone server listening on /home/kenz/.hprefix
Starting launch_daemon

Welcome to the Haiku shell.

.hyclone.log is:

• _hyclone.log

[trungnt2910]

I added pid/tid to log, it tells pid=-1. I should have uploaded entire log.

(This time, it doesn't stop before prompt w/ RelWithDebInfo build.)

_hyclone.log

How did you log the pid/tid? Using context.pid?