Debugging HPE ilorest command failing (error while loading shared libraries: libz.so.1)

Written by Claudio Kuenzler - 0 comments

Published on March 20th 2024 - Listed in Hardware Linux Monitoring Shell

---

HPE's Integrated Lights-Out Management (ILO) supports the Redfish BMC API since ILO4. This allows the user to query server information or execute ILO commands through this API.

The ilorest command

To make it easier, HPE released the ilorest command in 2016, which does the Redfish API communication in the background for you. From the official HP documentation:

HPE iLOrest is an open source and free of charge command-line interface that allows you to manage Hewlett Packard Enterprise products that take advantage of the Redfish RESTful API.

With iLOrest, you can manage HPE Gen9 servers running iLO 4 version 2.10 and later, HPE Gen10 servers running HPE iLO 5 version 1.20 and later and HPE Gen11 servers running HPE iLO 6 firmware 1.05 and later. You can install the tool on your computer for remote use or you can install the tool locally on a server with a Windows OS or Linux OS. All the distribution packages are available from GitHub.

But the command doesn't just work by connecting to a remote ILO IP address and login credentials - ilorest also works running locally on the HPE server (with elevated privileges). This is very helpful when the ILO interface is in a segmented or air-gapped network.

The following example shows how to retrieve some server information, such as hardware component status:

root@rhel9 ~ # ilorest --nocache serverinfo --json
Discovering data...Done
{
  "PowerSupply Redundancy Group 1": {
    "Redundancy Health": "OK",
    "Redundancy Mode": "Failover",
    "Redundancy State": "Enabled"
  },
  "fans": {
    "Fan 1": {
      "Health": "OK",
      "Hot Pluggable": true,
      "Location": "System",
      "Reading": "11%",
      "Redundant": true,
      "State": "Enabled"
    },
    "Fan 2": {
      "Health": "OK",
      "Hot Pluggable": true,
      "Location": "System",
      "Reading": "11%",
      "Redundant": true,
      "State": "Enabled"
    },
[...]

The ilorest command can be installed as RPM or DEB package from the HPE ilorest repositories.

ilorest not working, error points to library problem (but is misleading)

Under certain situations, depending on your server setup, you might run into the following problem when executing ilorest:

root@rhel9 ~ # ilorest
ilorest: error while loading shared libraries: libz.so.1: failed to map segment from shared object

The error hints to a problem loading a specific library (libz.so.1), however the library exists on the server and the command itself was correctly compiled against this library:

root@rhel9 ~ # ldd /usr/sbin/ilorest
    linux-vdso.so.1 (0x00007ffc245fc000)
    libdl.so.2 => /lib64/libdl.so.2 (0x00007f23b8afb000)
    libz.so.1 => /lib64/libz.so.1 (0x00007f23b8ae1000)
    libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f23b8adc000)
    libc.so.6 => /lib64/libc.so.6 (0x00007f23b88d3000)
    /lib64/ld-linux-x86-64.so.2 (0x00007f23b8b06000)

root@rhel9 ~ # ls -la /lib64/libz.so.1
lrwxrwxrwx 1 root root 14 Apr 15  2023 /lib64/libz.so.1 -> libz.so.1.2.11

root@rhel9 ~ # ls -la /lib64/libz.so.1.2.11
-rwxr-xr-x 1 root root 102552 Apr 15  2023 /lib64/libz.so.1.2.11

The library is clearly here and the permissions are readable for all. Why would ilorest have a problem loading this library?

Debugging ilorest command with strace

By debugging the ilorest command with strace (using -o to save the strace output in a file), something very interesting can be seen:

root@rhel9 ~ # strace -f -o /root/ilorest-strace.txt ilorest
ilorest: error while loading shared libraries: libz.so.1: failed to map segment from shared object

root@rhel9 ~ # more /root/ilorest-strace.txt
8399  execve("/usr/sbin/ilorest", ["ilorest"], 0x7ffc20b8bbf8 /* 23 vars */) = 0
8399  brk(NULL)                         = 0x117c000
[...]
8399  readlink("/proc/self/exe", "/usr/sbin/ilorest", 4095) = 17
8399  openat(AT_FDCWD, "/usr/sbin/ilorest", O_RDONLY) = 3
8399  newfstatat(3, "", {st_mode=S_IFREG|0755, st_size=14745680, ...}, AT_EMPTY_PATH) = 0
8399  newfstatat(3, "", {st_mode=S_IFREG|0755, st_size=14745680, ...}, AT_EMPTY_PATH) = 0
8399  lseek(3, 14745600, SEEK_SET)      = 14745600
8399  read(3, "\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0"..., 80) = 80
8399  lseek(3, 14737408, SEEK_SET)      = 14737408
8399  read(3, "ISTENT_MEMORY_COMMANDS/ApplyPmem"..., 4096) = 4096
8399  read(3, "tCommand.pyc\0\0\0\0\0\0P\0\255\322\357\0\0\17x\0\0\36D\1"..., 4096) = 4096
8399  read(3, "\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 80
8399  lseek(3, 14741504, SEEK_SET)      = 14741504
8399  read(3, "tCommand.pyc\0\0\0\0\0\0P\0\255\322\357\0\0\17x\0\0\36D\1"..., 4096) = 4096
8399  lseek(3, 14729216, SEEK_SET)      = 14729216
8399  read(3, "3.request)\3r\2\0\0\0i\323\260,\0i\255\t\0\0)\2\372\20ur"..., 4096) = 4096
8399  read(3, "x86_64-linux-gnu.so\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
8399  read(3, "tCommand.pyc\0\0\0\0\0\0P\0\255\322\357\0\0\17x\0\0\36D\1"..., 4096) = 4096
8399  close(3)                          = 0
8399  mkdir("/tmp/_MEITtQj17", 0700)    = 0
8399  stat("/tmp/_MEITtQj17/lib-dynload", 0x7ffc3d62ad00) = -1 ENOENT (No such file or directory)
8399  mkdir("/tmp/_MEITtQj17/lib-dynload", 0700) = 0
8399  stat("/tmp/_MEITtQj17/lib-dynload/_asyncio.cpython-38-x86_64-linux-gnu.so", 0x7ffc3d62ad00) = -1 ENOENT (No such file or directory)
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/lib-dynload/_asyncio.cpython-38-x86_64-linux-gnu.so", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/usr/sbin/ilorest", O_RDONLY) = 4
8399  newfstatat(4, "", {st_mode=S_IFREG|0755, st_size=14745680, ...}, AT_EMPTY_PATH) = 0
8399  lseek(4, 77824, SEEK_SET)         = 77824
8399  read(4, "e\366.ls\367S\27\27\23\231\351\207\20us\276\327\2\21lO!hi\330\16}\320\352@U"..., 577) = 577
8399  read(4, "x\332\354\275\v\\T\325\3668>3\200\216\240\f\245\26\231\326T\224X\212XZ\250q\3\1\35\24"..., 8192) = 8192
8399  newfstatat(3, "", {st_mode=S_IFREG|0640, st_size=0, ...}, AT_EMPTY_PATH) = 0
8399  write(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000B\0\0\0\0\0\0"..., 8192) = 8192
8399  write(3, "\330\350 \0\0\0\0\0\10\0\0\0\0\0\0\0\300\255\0\0\0\0\0\0\340\350 \0\0\0\0\0"..., 4096) = 4096
8399  write(3, "PM\0\0\0\0\0\0\370\365 \0\0\0\0\0\10\0\0\0\0\0\0\0 \356 \0\0\0\0\0"..., 4096) = 4096
8399  write(3, "\377%r\241 \0h,\0\0\0\351 \375\377\377\377%j\241 \0h-\0\0\0\351\20\375\377\377"..., 4096) = 4096
8399  read(4, "\213\357\342@V\36-\272A\251\n\217\313\347<\2706Q\345\0272[_\2M\223j\205i\270\231\271"..., 8192) = 8192
8399  write(3, "H\213G\20H\205\300t\7H\203\0\1\303f\220H\213\5\241\217 \0H\203\0\1\303\17\37@\0"..., 4096) = 4096
8399  write(3, "\341\377\377H\205\300I\211\305t51\322H\211\307H\211\3561\300\350V\340\377\377H\205\300tfH"..., 4096) = 4096
8399  write(3, "\0\0H\213\4\23H\205\300\17\204\221\0\0\0H\211\3371\3111\3221\366\377\320H\211\3371\322H"..., 4096) = 4096
8399  write(3, "\350;\276\377\377\353\203f\17\37\204\0\0\0\0\0\350+\276\377\377\3517\377\377\377f\17\37D\0\0"..., 4096) = 4096
8399  write(3, "\351\305\374\377\377\17\37\0001\366H\211\337\350\336\330\377\377\205\300\17\204\277\375\377\377f\17\37D\0\0"..., 4096) = 4096
8399  read(4, "\325\36/0\242\33XP\353\255tV\17\270*%-\345\352\201\371\316r\237\303\346\31X\314\253T\21"..., 8192) = 8192
8399  write(3, "\0\0H\211\337\350\326\235\377\377H\205\300H\211\5\334] \0\17\204\266\1\0\0H\203+\1\17\204"..., 4096) = 4096
8399  write(3, " `get_event_loop_policy().get_ev"..., 4096) = 4096
8399  write(3, "\n\nAdd a callback to be run when "..., 4096) = 4096
[...]

From the output above we can see, that ilorest creates a temporary directory inside /tmp (/tmp/_MEITtQj17) and looks for a library file inside it:

8399  stat("/tmp/_MEITtQj17/lib-dynload/_asyncio.cpython-38-x86_64-linux-gnu.so", 0x7ffc3d62ad00) = -1 ENOENT (No such file or directory)

As the file could not be found, it is created and the content of the file written (seen in the write operations in the output above):

8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/lib-dynload/_asyncio.cpython-38-x86_64-linux-gnu.so", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3

By looking at the full strace output, I realized that ilorest actually creates its own "environment" inside a temporary directory. This environment includes libraries (.so files) and Python scripts. Here's a (shortened) list:

root@rhel9 ~ # grep openat ilorest-strace.txt | grep O_WRONLY
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/lib-dynload/_asyncio.cpython-38-x86_64-linux-gnu.so", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[...]
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/libreadline.so.6", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/libssl.so.1.0.0", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/libtinfo.so.5", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/libz.so.1", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/base_library.zip", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[...]
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/COMMANDS/GetCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/COMMANDS/InfoCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/COMMANDS/ListCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/COMMANDS/LoadCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[...]
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/RawDeleteCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/RawGetCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/RawHeadCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/RawPatchCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/RawPostCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/RawPutCommand.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/RAW_COMMANDS/__init__.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[...]
8399  openat(AT_FDCWD, "/tmp/_MEITtQj17/extensions/iLO_REPOSITORY_COMMANDS/__init__.pyc", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3

EPERM (Operation not permitted) on execution

Continuing the strace output, eventually there comes the part where the error happens. Interestingly this happened inside a child process (8400):

8400  openat(AT_FDCWD, "/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
8400  read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\20\0\0\0\0\0\0"..., 832) = 832
8400  newfstatat(3, "", {st_mode=S_IFREG|0755, st_size=15464, ...}, AT_EMPTY_PATH) = 0
8400  mmap(NULL, 16424, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5e838d3000
8400  mmap(0x7f5e838d4000, 4096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7f5e838d4000
8400  mmap(0x7f5e838d5000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f5e838d5000
8400  mmap(0x7f5e838d6000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f5e838d6000
8400  close(3)                          = 0
8400  openat(AT_FDCWD, "/tmp/_MEITtQj17/libz.so.1", O_RDONLY|O_CLOEXEC) = 3
8400  read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P#\0\0\0\0\0\0"..., 832) = 832
8400  newfstatat(3, "", {st_mode=S_IFREG|0700, st_size=88216, ...}, AT_EMPTY_PATH) = 0
8400  mmap(NULL, 2183304, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = -1 EPERM (Operation not permitted)
8400  close(3)                          = 0
8400  writev(2, [{iov_base="ilorest", iov_len=7}, {iov_base=": ", iov_len=2}, {iov_base="error while loading shared libra"..., iov_len=36}, {iov_base=": ", iov_len=2}, {iov_base="libz.so.1"
, iov_len=9}, {iov_base=": ", iov_len=2}, {iov_base="failed to map segment from share"..., iov_len=40}, {iov_base="", iov_len=0}, {iov_base="", iov_len=0}, {iov_base="\n", iov_len=1}], 10)
= 99
8400  exit_group(127)                   = ?
8400  +++ exited with 127 +++
8399  <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 127}], 0, NULL) = 8400
8399  --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8400, si_uid=0, si_status=127, si_utime=0, si_stime=0} ---

From this output we can see several steps:

The library libz.so.1 is read. Which obviously worked as this library was created earlier and would have shown a ENOENT error if it did not exist:

8400  openat(AT_FDCWD, "/tmp/_MEITtQj17/libz.so.1", O_RDONLY|O_CLOEXEC) = 3

The next step uses mmap with the PROT_EXEC flag - and it runs into an error: EPERM (Operation not permitted):

8400  mmap(NULL, 2183304, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = -1 EPERM (Operation not permitted)

As mmap() ran into an error, the command uses writev() to send an error to stderr, which we saw on the command line output:

8400  writev(2, [{iov_base="ilorest", iov_len=7}, {iov_base=": ", iov_len=2}, {iov_base="error while loading shared libra"..., iov_len=36}, {iov_base=": ", iov_len=2}, {iov_base="libz.so.1"
, iov_len=9}, {iov_base=": ", iov_len=2}, {iov_base="failed to map segment from share"..., iov_len=40}, {iov_base="", iov_len=0}, {iov_base="", iov_len=0}, {iov_base="\n", iov_len=1}], 10)
= 99

And finally the child process exits with an error (127) and consequently also terminates the parent process (8399):

8400  exit_group(127)                   = ?
8400  +++ exited with 127 +++
8399  <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 127}], 0, NULL) = 8400
8399  --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8400, si_uid=0, si_status=127, si_utime=0, si_stime=0} ---

This means: The error pointing to the library libz.so.1 is more a coincidence, as this was the last library loaded before mmap() tried to execute the process. The real and more helpful error would be: EPERM (Operation not permitted).

But what does this error mean? According to the mmap documentation:

mmap() creates a new mapping in the virtual address space of the calling process.

       The prot argument describes the desired memory protection of the mapping (and must not conflict with the open mode of the file). It is either PROT_NONE or the bitwise OR of one or more of the following flags:

       PROT_EXEC Pages may be executed.

       PROT_READ Pages may be read.

       PROT_WRITE Pages may be written.

       PROT_NONE Pages may not be accessed.

Further down in the same documentation we can also spot error messages, specific to the PROT_EXEC flag:

ERRORS   
EPERM  The prot argument asks for PROT_EXEC but the mapped area belongs to a file on a filesystem that was mounted no-exec.

The documentation makes a very important hint: The EPERM error shows up when mmap tries to execute a mapped page (PROT_EXEC) inside a no-exec file system.

/tmp partition mounted with noexec option

With that new knowledge at hand, let's verify the /tmp mount:

root@rhel9 ~ # mount | grep /tmp
/dev/mapper/vgsystem-lvtmp on /tmp type ext4 (rw,nosuid,nodev,noexec,relatime,seclabel)

Holy macaroni! The noexec mount option is indeed set on /tmp! No wonder nothing can be executed inside this partition!

Use a different TMPDIR instead

The SHELL environment variable TMPDIR specifies which path to use for temporary directories. The default TMPDIR value in most Unix and POSIX systems (this includes Linux) is /tmp.

But as this is a variable, this means we can also set a different value for this - at least for the Shell session which executes ilorest. Let's try another partition, which is mounted without noexec:

root@rhel9 ~ # mkdir /root/ilorest_tmp
root@rhel9 ~ # export TMPDIR=/root/ilorest_tmp
root@rhel9 ~ # ilorest --nocache serverinfo --json
Discovering data...Done
{
  "PowerSupply Redundancy Group 1": {
    "Redundancy Health": "OK",
    "Redundancy Mode": "Failover",
    "Redundancy State": "Enabled"
  },
  "fans": {
    "Fan 1": {
      "Health": "OK",
      "Hot Pluggable": true,
      "Location": "System",
      "Reading": "11%",
      "Redundant": true,
      "State": "Enabled"
    },
[...]

The ilorest command ran successfully this time!

Another strace debug of this command revealed that the ilorest environment (including the .so libraries and Python files) were now created under a temporary directory in /root/ilorest_tmp/_MEIDjHTsd/.

Add a comment

Show form to leave a comment

Comments (newest first)

No comments yet.