Bug#1038422: ntpsec: ntpd segmentation fault in libcrypto.so[7f6d3ecc5000+278000]

[forest . owlet]

Hi Richard,

I'm sorry for my tardy response.  I just returned from holiday.

On 2023-07-23 05:11, Richard Laager wrote:
> Some questions from upstream, with my commentary added...
> 
>> How busy is this sustem? Is it just a simple client or also a server? If 
>> server, how busy?
This is a server and participates in the NTP Pool project, so the NTPsec
process is fairly busy.  From the logs the server is handling about 1.5
to 1.7 million NTP requests per hour.

>> 
>> From the stack trace, the server side is trying to decode a NTS cookie. Is 
>> this box setup as a NTS server? That needs a certificate and key so it takes 
>> more than just upgrading from bullseye to bookworm.
> 
> It's not, right? We previously established that this is using the stock 
> ntp.conf?
> 
No, it is not configured as an NTS server.

>> What are the chances that a valid NTP request with NTS arrived at this 
>> system? ntpq -c ntsinfo will show counters.
>
I'd say the chances are fairly high that an invalid NTP request with NTS
has arrived.  But the counters are all zero.
cyclone@karita:~$ ntpq -c ntsinfo
NTS client sends:   0
NTS client recvs good:  0
NTS client recvs w error:   0
NTS server recvs good:  0
NTS server recvs w error:   0
NTS server sends:   0
NTS make cookies:   0
NTS decode cookies: 0
NTS decode cookies old: 0
NTS decode cookies old2:0
NTS decode cookies older:   0
NTS decode cookies too old: 0
NTS decode cookies error:   0
NTS KE client probes good:  0
NTS KE client probes bad:   0
NTS KE serves good: 0
NTS KE serves bad:  0
cyclone@karita:~$
 
> It would be good if you could check this. But if an NTS request is crashing 
> ntpd, you might never see non-zero counters.
> 
>> The log file from starting up might be helpful.

Here's the syslog entries from the most recent restart.  I took the
liberty of scrubbing the high portions of the IP addresses.

2023-07-28T06:58:39.890236+00:00 karita ntpd[30320]: INIT: ntpd
ntpsec-1.2.2: Starting
2023-07-28T06:58:39.891073+00:00 karita ntpd[30320]: INIT: Command line:
/usr/sbin/ntpd -p /run/ntpd.pid -c /etc/ntpsec/ntp.conf -g -N -u
ntpsec:ntpsec
2023-07-28T06:58:39.891132+00:00 karita ntp-systemd-wrapper[30320]:
2023-07-28T06:58:39 ntpd[30320]: INIT: ntpd ntpsec-1.2.2: Starting
2023-07-28T06:58:39.892382+00:00 karita ntp-systemd-wrapper[30320]:
2023-07-28T06:58:39 ntpd[30320]: INIT: Command line: /usr/sbin/ntpd -p
/run/ntpd.pid -c /etc/ntpsec/ntp.conf -g -N -u ntpsec:ntpsec
2023-07-28T06:58:39.892502+00:00 karita systemd[1]: Started
ntpsec.service - Network Time Service.
2023-07-28T06:58:39.894804+00:00 karita ntpd[30322]: INIT: precision =
0.060 usec (-24)
2023-07-28T06:58:39.895396+00:00 karita ntpd[30322]: INIT: successfully
locked into RAM
2023-07-28T06:58:39.899405+00:00 karita ntpd[30322]: CONFIG: readconfig:
parsing file: /etc/ntpsec/ntp.conf
2023-07-28T06:58:39.899544+00:00 karita ntpd[30322]: CONFIG: restrict
nopeer ignored
2023-07-28T06:58:39.900054+00:00 karita ntpd[30322]: CLOCK: leapsecond
file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature
2023-07-28T06:58:39.900121+00:00 karita ntpd[30322]: CLOCK: leapsecond
file ('/usr/share/zoneinfo/leap-seconds.list'): loaded,
expire=2023-12-28T00:00Z last=2017-01-01T00:00Z ofs=37
2023-07-28T06:58:39.900198+00:00 karita ntpd[30322]: INIT: Using
SO_TIMESTAMPNS(ns)
2023-07-28T06:58:39.900262+00:00 karita ntpd[30322]: IO: Listen and drop
on 0 v6wildcard [::]:123
2023-07-28T06:58:39.900367+00:00 karita ntpd[30322]: IO: Listen and drop
on 1 v4wildcard 0.0.0.0:123
2023-07-28T06:58:39.900518+00:00 karita ntpd[30322]: IO: Listen normally
on 2 lo 127.0.0.1:123
2023-07-28T06:58:39.900589+00:00 karita ntpd[30322]: IO: Listen normally
on 3 eth0 xxx.yyy.zzz.201:123
2023-07-28T06:58:39.900662+00:00 karita ntpd[30322]: IO: Listen normally
on 4 lo [::1]:123
2023-07-28T06:58:39.900913+00:00 karita ntpd[30322]: IO: Listen normally
on 5 eth0 [::::5ce7]:123
2023-07-28T06:58:39.901000+00:00 karita ntpd[30322]: IO: Listen normally
on 6 eth0 [fe80:::::dfe%2]:123
2023-07-28T06:58:39.901065+00:00 karita ntpd[30322]: IO: Listening on
routing socket on fd #23 for interface updates
2023-07-28T06:58:39.912520+00:00 karita ntpd[30322]: INIT: MRU 10922
entries, 13 hash bits, 65536 bytes
2023-07-28T06:58:39.912607+00:00 karita ntpd[30322]: INIT: Built with
OpenSSL 3.0.7 1 Nov 2022, 3070
2023-07-28T06:58:39.912652+00:00 karita ntpd[30322]: INIT: Running with
OpenSSL 3.0.9 30 May 2023, 3090
2023-07-28T06:58:39.912976+00:00 karita ntpd[30322]: NTSc: Using system
default root certificates.
2023-07-28T06:58:42.938515+00:00 karita ntpd[30322]: DNS: dns_probe:
0.debian.pool.ntp.org, cast_flags:8, flags:101
2023-07-28T06:58:42.957881+00:00 karita 

Bug#1038422: ntpsec: ntpd segmentation fault in libcrypto.so[7f6d3ecc5000+278000]

[forest . owlet]

Hi,

Here's a backtrace from the latest ntpsec coredump.

root@karita:/var/lib/systemd/coredump# export
DEBUGINFOD_URLS="https://debuginfod.debian.net;
root@karita:/var/lib/systemd/coredump# coredumpctl debug
  PID: 61726 (ntpd)
   UID: 110 (ntpsec)
   GID: 117 (ntpsec)
Signal: 11 (SEGV)
 Timestamp: Fri 2023-06-30 02:33:27 UTC (59min ago)
  Command Line: /usr/sbin/ntpd -p /run/ntpd.pid -c /etc/ntpsec/ntp.conf
-g -N -u ntpsec:ntpsec
Executable: /usr/sbin/ntpd
 Control Group: /system.slice/ntpsec.service
  Unit: ntpsec.service
 Slice: system.slice
   Boot ID: 0e943a6b0cfe4fdd9e032c3d91c9d58d
Machine ID: 0e50b80b858599a4a8aa8383662e5bb4
  Hostname: karita
   Storage:
/var/lib/systemd/coredump/core.ntpd.110.0e943a6b0cfe4fdd9e032c3d91c9d58d.61726.168809240700.zst
(present)
  Size on Disk: 775.6K
   Message: Process 61726 (ntpd) of user 110 dumped core.

Module libnss_systemd.so.2 from deb
systemd-252.6-1.amd64
Stack trace of thread 61726:
#0  0x7f280d4e0ab3 aesni_set_encrypt_key
(libcrypto.so.3 + 0xe0ab3)
#1  0x7f280d6f3d45 cipher_hw_aesni_initkey
(libcrypto.so.3 + 0x2f3d45)
#2  0x7f280d7397fb cipher_generic_init_internal
(libcrypto.so.3 + 0x3397fb)
#3  0x7f280d7398cb ossl_cipher_generic_einit
(libcrypto.so.3 + 0x3398cb)
#4  0x7f280d60993b EVP_CipherInit_ex (libcrypto.so.3
+ 0x20993b)
#5  0x560b2e1246f3 AES_SIV_Init (ntpd + 0x4c6f3)
#6  0x560b2e1255df AES_SIV_Decrypt (ntpd + 0x4d5df)
#7  0x560b2e10f40d nts_unpack_cookie (ntpd +
0x3740d)
#8  0x560b2e10f85b extens_server_recv (ntpd +
0x3785b)
#9  0x560b2e0f78ce receive (ntpd + 0x1f8ce)
#10 0x560b2e0ed8ea read_network_packet (ntpd +
0x158ea)
#11 0x560b2e0ef3cf input_handler (ntpd + 0x173cf)
#12 0x560b2e0e819f mainloop (ntpd + 0x1019f)
#13 0x7f280d16718a __libc_start_call_main (libc.so.6
+ 0x2718a)
#14 0x7f280d167245 __libc_start_main_impl (libc.so.6
+ 0x27245)
#15 0x560b2e0e84e1 _start (ntpd + 0x104e1)
ELF object binary architecture: AMD x86-64

GNU gdb (Debian 13.1-3) 13.1
Copyright (C) 2023 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later

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-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
.
Find the GDB manual and other documentation resources online at:
.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/ntpd...
Reading symbols from
/usr/lib/debug/.build-id/8b/c6f9398efb6b8c446b2d719831f5738d563c84.debug...
[New LWP 61726]

This GDB supports auto-downloading debuginfo from the following URLs:
  
Enable debuginfod for this session? (y or [n]) y
Debuginfod has been enabled.
To make this setting permanent, add 'set debuginfod enabled on' to
.gdbinit.
Downloading separate debug info for
/lib/x86_64-linux-gnu/libnss_systemd.so.2
Downloading separate debug info for /lib/x86_64-linux-gnu/libgcc_s.so.1
Downloading separate debug info for system-supplied DSO at
0x7ffc94772000
[Thread debugging using libthread_db enabled]
Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/ntpd -p /run/ntpd.pid -c
/etc/ntpsec/ntp.conf -g -N -u ntpsec:ntpsec'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  aesni_set_encrypt_key () at crypto/aes/aesni-x86_64.s:4104
Download failed: Invalid argument.  Continuing without source file
./build_shared/crypto/aes/aesni-x86_64.s.
4104crypto/aes/aesni-x86_64.s: No such file or directory.
(gdb) bt
#0  aesni_set_encrypt_key () at crypto/aes/aesni-x86_64.s:4104
#1  0x7f280d6f3d45 in cipher_hw_aesni_initkey (dat=0x560b2f082b50,
key=, keylen=)
at ../providers/implementations/ciphers/cipher_aes_hw_aesni.inc:37
#2  0x7f280d7397fb in cipher_generic_init_internal
(ctx=0x560b2f082b50,
key=0x10 , keylen=16,
iv=0x0,
ivlen=0, params=0x0, enc=1)
at ../providers/implementations/ciphers/ciphercommon.c:218
#3  0x7f280d7398cb in ossl_cipher_generic_einit (vctx=,
key=, keylen=, iv=,
ivlen=, params=)
at ../providers/implementations/ciphers/ciphercommon.c:228
#4  0x7f280d60993b in EVP_CipherInit_ex (ctx=,
cipher=, impl=impl@entry=0x0, key=,
iv=iv@entry=0x0, 

Bug#1038422: ntpsec: ntpd segmentation fault in libcrypto.so[7f6d3ecc5000+278000]

[forest . owlet]

On 2023-06-28 02:39, Richard Laager wrote:
> The original submitter replied off the tracker (probably by accident). I'll 
> summarize here.
> 
> The ntp.conf he included is the stock ntp.conf.
> 
> He indicated he will try to get a backtrace.

I'm trying to setup ntpsec to get a backtrace.  I installed the
ntpsec-dbgsym package, but I'm not sure that I did it correctly. 
Shouldn't the output from this file command include the text "no
stripped".

root@karita:/home/root# file /usr/sbin/ntpd
/usr/sbin/ntpd: ELF 64-bit LSB pie executable, x86-64, version 1 (SYSV),
dynamically linked, interpreter /lib64/ld-linux-x86-64.so.2,
BuildID[sha1]=8bc6f9398efb6b8c446b2d719831f5738d563c84, for GNU/Linux
3.2.0, stripped
root@karita:/home/root#

Regards,


Roy