SIGSEGV, apparently when clearing record cache

[heikojansen]

We run a fairly busy yazproxy between our (meta-) search portal and a number of Z39.50 targets, using the latest released versions of YAZ, yazpp and yazproxy.
We see approximately 10 to 15 core dumps a day with almost identical backtraces:

#0  0x00007fc37d06f467 in nmem_reset () from /usr/lib64/libyaz.so.5
#1  0x00007fc37d06f6ee in nmem_destroy () from /usr/lib64/libyaz.so.5
#2  0x00007fc37d19a7e4 in yazpp_1::RecordCache::clear (this=this@entry=0x5616efbcb6d8) at yaz-z-cache.cpp:56
#3  0x00007fc37d1b06c9 in Yaz_Proxy::get_client (this=this@entry=0x5616efa40550, apdu=apdu@entry=0x5616efc5d4d0, cookie=0x5616efc5ddc8 "749c6a6e7168a5665858652510c446d98f502dfb", proxy_host=<optimized out>,
proxy_host@entry=0x5616efc5dd28 "[HOST_PORT_DB_002]", http_code=http_code@entry=0x7ffc14cb8314) at yaz-proxy.cpp:677
#4  0x00007fc37d1b3393 in Yaz_Proxy::handle_incoming_Z_PDU (this=this@entry=0x5616efa40550, apdu=0x5616efc5d4d0) at yaz-proxy.cpp:3622
#5  0x00007fc37d1b1e84 in Yaz_Proxy::recv_GDU_normal (this=this@entry=0x5616efa40550, gdu=gdu@entry=0x5616ef967560) at yaz-proxy.cpp:2208
#6  0x00007fc37d1b1f69 in Yaz_Proxy::recv_GDU_reduce (this=this@entry=0x5616efa40550, gdu=gdu@entry=0x5616ef967560) at yaz-proxy.cpp:2183
#7  0x00007fc37d1b20ed in Yaz_Proxy::recv_GDU_more (this=0x5616efa40550, normal=<optimized out>) at yaz-proxy.cpp:2195
#8  0x00007fc37d196e48 in yazpp_1::PDU_Assoc::socketNotify (this=0x5616efbcff70, event=<optimized out>) at yaz-pdu-assoc.cpp:273
#9  0x00007fc37d195e46 in yazpp_1::SocketManager::Rep::inspect_poll_result (this=0x5616ef974240, res=1, fds=<optimized out>, no_fds=92, timeout=2) at yaz-socket-manager.cpp:226
#10 0x00007fc37d19620d in yazpp_1::SocketManager::processEvent (this=this@entry=0x7ffc14cb8700) at yaz-socket-manager.cpp:310
#11 0x00005616ef5eb808 in child_run (data=0x7ffc14cb8700) at yaz-proxy-main.cpp:251
#12 0x00007fc37d0b022b in keepalive () from /usr/lib64/libyaz.so.5
#13 0x00007fc37d0b069b in yaz_daemon () from /usr/lib64/libyaz.so.5
#14 0x00005616ef5eb5db in main (argc=9, argv=0x7ffc14cb8c08) at yaz-proxy-main.cpp:271

Sometimes a call to free() is reported as the final step beyond nmem_reset().
It can happen with any target.

I have attached the proxy config:
yazproxy_cfg.txt,

some info pertaining to the core:
yazproxy_core.txt,

and the log file from about 5 seconds before and after the SEGV:
yazproxy_core.log

Hopefully that'll be enough info to locate the problem.
Otherwise please let me know if there is any other information I could provide.

Thx!
Heiko

[heikojansen]

I'm not exactly sure, but this might be connected to the proprietary "session cookie" feature?
Each "Received SIGSEGV from child ..." warning in the logfile seems to be preceded by a log entry

17:22:24-11/04 [log] 1712848944:1170 1  REOPEN target=host.name:Port/Database

It is not immediately obvious, but there are two spaces between the "1" and the "REOPEN"; the code here actually is

yaz_log(YLOG_LOG, "%s REOPEN target=%s", m_session_str,
                             c->get_hostname());

(see source)
and m_session_str probably should not be empty?

Our frontend might send a request to the yazproxy with a certain "cookie" value and then - while that request is still being processed by yazproxy (e.g., communicating with the backend target) - send another request to the proxy with the same cookie value (which is derived from the query itself).
Could this lead to some allocated memory being freed but then used again?

I will try to temporarily disable the cookie param in our frontend and report back if that makes the SIGSEGVs disappear. I will then need to analyze if that has any measurable influence on the performance of our frontend from the perspective of our users.