Segmentation fault when issue persistent-event-log with json output format

[yalanliufio]

With latest release 2.13, when try to issue a persistent-event-log with json output encounter Segmentation fault, no json output works fine.

nvme --version
nvme version 2.13 (git 2.13)
libnvme version 1.13 (git 1.13)

Here are the command sequences used for the test:

1. nvme persistent-event-log /dev/nvme7 -a 1
   Establishing Persistent Event Log Context

2. nvme persistent-event-log /dev/nvme7 -a 1 -l 1024
   command passes without error

3. nvme persistent-event-log /dev/nvme7 -a 1 -l 4096
   command passes without error

4. nvme persistent-event-log /dev/nvme7 -a 0 -l 512 -o json
   command passes without error

5. nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
   Segmentation fault (core dumped)

6. nvme persistent-event-log /dev/nvme7 -a 0 -l 4096 -o json
   Segmentation fault (core dumped)

7. nvme persistent-event-log /dev/nvme7 -a 2
   Releasing Persistent Event Log Context

I have tried to switch back the old version 2.2.1, it works fine without this problem. Same firmware and same OS, just change nvme cli version.

[yalanliufio]

This is var/log/messages when Segmentation fault happen:

May 12 15:13:01 sm-120u-120 kernel: nvme[28652]: segfault at 2028008 ip 000000000044e5e3 sp 00007ffe9fd7cd50 error 4 in nvme[400000+12a000]
May 12 15:13:01 sm-120u-120 kernel: Code: ff be c8 ae 4d 00 48 89 df 48 89 c2 e8 66 92 fb ff 0f b6 7d df e8 5d 94 fb ff be cf ae 4d 00 48 89 df 48 89 c2 e8 4d 92 fb ff <8b> 7d ec e8 45 94 fb ff be da ae 4d 00 48 89 df 48 89 c2 e8 35 92
May 12 15:13:01 sm-120u-120 systemd[1]: Started Process Core Dump (PID 28653/UID 0).
May 12 15:13:01 sm-120u-120 systemd-coredump[28654]: Resource limits disable core dumping for process 28652 (nvme).
May 12 15:13:01 sm-120u-120 systemd-coredump[28654]: Process 28652 (nvme) of user 0 dumped core.
May 12 15:13:01 sm-120u-120 systemd[1]: systemd-coredump@18-28653-0.service: Succeeded.
(.venv) [root@sm-120u-120 test-scripts]#

[igaw]

Do you happen to have a backtrace? My local test devices don't support persistent-event-log. Can't spot any changes which could explain this crash.

[yalanliufio]

@igaw I don't have one now, could you let me know the steps to get a backtrace and I will try it? thank you!

[martin-belanger]

Hi @yalanliufio - It looks like systemd-coredump is running on your system. Do you also have coredumpctl installed? If so, try the following (note that you may need to use sudo with these commands):

coredumpctl list nvme   # List all the coredumps related to nvme.

coredumpctl info [PID]  # PID is one of the PIDs from the list above

Hope this helps.

[yalanliufio]

@martin-belanger Thank you!

This is the info I got:

nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
Segmentation fault (core dumped)

(.venv) [root@sm-120u-120 test-scripts]# cat /var/log/messages
........
May 13 11:04:44 sm-120u-120 kernel: nvme[77678]: segfault at 1789000 ip 000000000044e5e3 sp 00007ffde29f59f0 error 4 in nvme[400000+12a000]
May 13 11:04:44 sm-120u-120 kernel: Code: ff be c8 ae 4d 00 48 89 df 48 89 c2 e8 66 92 fb ff 0f b6 7d df e8 5d 94 fb ff be cf ae 4d 00 48 89 df 48 89 c2 e8 4d 92 fb ff <8b> 7d ec e8 45 94 fb ff be da ae 4d 00 48 89 df 48 89 c2 e8 35 92
May 13 11:04:44 sm-120u-120 systemd[1]: Started Process Core Dump (PID 77679/UID 0).
May 13 11:04:44 sm-120u-120 systemd-coredump[77680]: Resource limits disable core dumping for process 77678 (nvme).
May 13 11:04:44 sm-120u-120 systemd-coredump[77680]: Process 77678 (nvme) of user 0 dumped core.
May 13 11:04:44 sm-120u-120 systemd[1]: systemd-coredump@26-77679-0.service: Succeeded.
(.venv) [root@sm-120u-120 test-scripts]#

(.venv) [root@sm-120u-120 test-scripts]# coredumpctl list nvme
.....
Mon 2025-05-12 15:37:27 MDT 30461 0 0 11 none /usr/local/sbin/nvme
Tue 2025-05-13 09:49:16 MDT 73131 0 0 11 none /usr/local/sbin/nvme
Tue 2025-05-13 09:55:09 MDT 73792 0 0 11 none /usr/local/sbin/nvme
Tue 2025-05-13 09:55:46 MDT 73979 0 0 11 none /usr/local/sbin/nvme
Tue 2025-05-13 11:01:16 MDT 76808 0 0 11 none /usr/local/sbin/nvme
Tue 2025-05-13 11:02:56 MDT 77148 0 0 11 none /usr/local/sbin/nvme
Tue 2025-05-13 11:04:44 MDT 77678 0 0 11 none /usr/local/sbin/nvme
lines 3-28/28 (END)

(.venv) [root@sm-120u-120 test-scripts]# coredumpctl info 77678
PID: 77678 (nvme)
UID: 0 (root)
GID: 0 (root)
Signal: 11 (SEGV)
Timestamp: Tue 2025-05-13 11:04:44 MDT (1min 28s ago)
Command Line: nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
Executable: /usr/local/sbin/nvme
Control Group: /user.slice/user-0.slice/session-233.scope
Unit: session-233.scope
Slice: user-0.slice
Session: 233
Owner UID: 0 (root)
Boot ID: 690d5884cca14c3b84dfdd3b4c381c00
Machine ID: 483ab17e342f4f859903f7d363b5c676
Hostname: sm-120u-120
Storage: none
Message: Process 77678 (nvme) of user 0 dumped core.

[martin-belanger]

Unfortunately, there is no stack trace. Did you run coredumpctl info as root?

Usually, coredumpctl info [PID] prints the stack trace at the end (just after the Message: Process ... line.

Here's an example from a random coredump on my system (this is not an nvme coredump, unfortunately). You can see a Stack trace at the end like this one.

[...]
Hostname: blah
Storage: none
       Message: Process 638807 (mpirun) of user 1000 dumped core.
                
                Module libgcc_s.so.1 from deb gcc-14-14.2.0-4ubuntu2~24.04.amd64
                Module libstdc++.so.6 from deb gcc-14-14.2.0-4ubuntu2~24.04.amd64
                Module libudev.so.1 from deb systemd-255.4-1ubuntu8.4.amd64
                Stack trace of thread 638807:
                #0  0x000071ff2dd1ba61 __GI___libc_read (libc.so.6 + 0x11ba61)
                #1  0x000071ff29fe258f n/a (libnvidia-opencl.so.1 + 0x5e258f)
                #2  0x000071ff29fe2712 n/a (libnvidia-opencl.so.1 + 0x5e2712)
                #3  0x000071ff29fe0c0e n/a (libnvidia-opencl.so.1 + 0x5e0c0e)
                #4  0x000071ff29fdc440 n/a (libnvidia-opencl.so.1 + 0x5dc440)

                [...]  

                ELF object binary architecture: AMD x86-64

[yalanliufio]

yes, it is root
I asked my coworker, he suggested to do a strace like this:
strace -o strace_output.txt nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
output file is attached, see if it helps
strace_output.txt

[igaw]

The simplest way to gather a backtrace to run it under gdb. You might have to debug symbols by hand, modern distros have infrastructure in place so gdb downloads debuginfo directly.

# gdb --args nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
[...]

(gdb) run
Starting program: /usr/sbin/nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
[crash]
(gdb) bt full

[ikegami-t]

Can you test other versions between v2.2.1 OK version and v2.13 NG version since there are many changes between the versions then difficult to investigate from the source code? Seems possible to be related below but not sure.

1. The log length is possible to be not handled correctly by the output functions basically.
2. The memory allocation functions are changed as below.

v2.2.1

static int get_persistent_event_log(int argc, char **argv,
		struct command *cmd, struct plugin *plugin)
{
...
	pevent = calloc(sizeof(*pevent), 1);
...
	pevent_log_info = nvme_alloc(cfg.log_len, &huge);

latest master (probably same with v2.13)

static int get_persistent_event_log(int argc, char **argv,
		struct command *cmd, struct plugin *plugin)
...
	pevent = nvme_alloc(sizeof(*pevent));
...
	pevent_log_info = nvme_alloc_huge(cfg.log_len, &mh);

[igaw]

Could you also post the output of

nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json -vv

I see nvme-cli crashes after the third command has been issued. From a quick look I can't say which command that was.

openat(AT_FDCWD, "/dev/nvme7", O_RDONLY) = 3
fstat(3, {st_mode=S_IFCHR|0600, st_rdev=makedev(0xf2, 0x7), ...}) = 0
ioctl(3, NVME_IOCTL_ADMIN_CMD, 0x7fffb280e370) = 0
ioctl(3, NVME_IOCTL_ADMIN_CMD, 0x7fffb280e370) = 0
ioctl(3, NVME_IOCTL_ADMIN_CMD, 0x7fffb280e370) = 0
stat("/dev/urandom", {st_mode=S_IFCHR|0666, st_rdev=makedev(0x1, 0x9), ...}) = 0
openat(AT_FDCWD, "/dev/urandom", O_RDONLY) = 4
read(4, "\205Xu%", 4)                   = 4
close(4)                                = 0
--- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0xfef000} ---
+++ killed by SIGSEGV (core dumped) +++

[yalanliufio]

(.venv) [root@sm-120u-120 test-scripts]# nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json -vv
opcode : 02
flags : 00
rsvd1 : 0000
nsid : ffffffff
cdw2 : 00000000
cdw3 : 00000000
data_len : 00000200
metadata_len : 00000000
addr : 25f0000
metadata : 0
cdw10 : 007f000d
cdw11 : 00000000
cdw12 : 00000000
cdw13 : 00000000
cdw14 : 00000000
cdw15 : 00000000
timeout_ms : 00000000
result : 00000000
err : 0
latency : 369 us
opcode : 02
flags : 00
rsvd1 : 0000
nsid : ffffffff
cdw2 : 00000000
cdw3 : 00000000
data_len : 00000400
metadata_len : 00000000
addr : 25f2000
metadata : 0
cdw10 : 00ff000d
cdw11 : 00000000
cdw12 : 00000000
cdw13 : 00000000
cdw14 : 00000000
cdw15 : 00000000
timeout_ms : 00000000
result : 00000000
err : 0
latency : 299 us
opcode : 02
flags : 00
rsvd1 : 0000
nsid : ffffffff
cdw2 : 00000000
cdw3 : 00000000
data_len : 00000200
metadata_len : 00000000
addr : 25f0000
metadata : 0
cdw10 : 007f000d
cdw11 : 00000000
cdw12 : 00000000
cdw13 : 00000000
cdw14 : 00000000
cdw15 : 00000000
timeout_ms : 00000000
result : 00000000
err : 0
latency : 292 us
Segmentation fault (core dumped)
(.venv) [root@sm-120u-120 test-scripts]#

[yalanliufio]

@ikegami-t
I tested the version 2.9.1, and it has the same problem, it even worse as the command without json also core dumped
here are all the output:
(.venv) [root@sm-120u-120 test-scripts]# nvme --version
nvme version 2.9.1 (git 2.9.1)
libnvme version 1.9 (git 1.9)
(.venv) [root@sm-120u-120 test-scripts]# nvme persistent-event-log /dev/nvme7 -a 1
Establishing Persistent Event Log Context
(.venv) [root@sm-120u-120 test-scripts]# nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
Segmentation fault (core dumped)
(.venv) [root@sm-120u-120 test-scripts]# nvme persistent-event-log /dev/nvme7 -a 0 -l 1024
Persistent Event Log for device: nvme7
Action for Persistent Event Log: 0
Log Identifier: 13
Total Number of Events: 7094
Total Log Length : 537070
Log Revision: 3
....
....
double free or corruption (!prev)
Aborted (core dumped)

For nvme verison 2.13, at lease command without json format works fine.

[igaw]

It doesn't look like that the nvme commands fail, instead I suspect the json printing code is broken, e.g. json_pevent_entry

the gdb output would be very helpful.

[yalanliufio]

@igaw
This is gdb output, but looks like my gdb not setup right

(.venv) [root@sm-120u-120 test-scripts]# nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
Segmentation fault (core dumped)
(.venv) [root@sm-120u-120 test-scripts]# gdb --args nvme persistent-event-log /dev/nvme7 -a 0 -l 1024 -o json
GNU gdb (GDB) Red Hat Enterprise Linux 8.2-19.el8
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
http://www.gnu.org/software/gdb/bugs/.
Find the GDB manual and other documentation resources online at:
http://www.gnu.org/software/gdb/documentation/.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from nvme...done.
(gdb)
(gdb)
(gdb)
(gdb)
(gdb)
then keep in this (gdb) loop forever