Bug 1896808

Summary:	NSS sometimes causes CURL deadlocks
Product:	Red Hat Enterprise Linux 7	Reporter:	Josef Kubin <jkubin>
Component:	nss	Assignee:	nss-nspr-maint <nss-nspr-maint>
Status:	CLOSED ERRATA	QA Contact:	Ivan Nikolchev <inikolch>
Severity:	high	Docs Contact:
Priority:	medium
Version:	7.8	CC:	ashaya, gbowyer, inikolch, jreznik, msauton, rrelyea, ssorce
Target Milestone:	rc	Keywords:	Triaged, ZStream
Target Release:	---	Flags:	pm-rhel: mirror+
Hardware:	Unspecified
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-10-12 15:26:38 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Josef Kubin 2020-11-11 15:21:06 UTC

Description of problem:
After upgrading the NSS package to v3.53 our custom cronjobs keep in hanging state.
The problem occurs with random cron jobs, but not always.
It happens, when our PHP script is using CURL to call HTTPS endpoint to update files, and it just hangs there.

Version-Release number of selected component (if applicable):

nss-3.53.1-3.el7_9.x86_64  <--- this NSS version sometimes stuck
nss-3.44.0-7.el7_7.x86_64  <--- this NSS version works reliably

How reproducible:
Sometimes

The process is waiting for __lll_lock_wait () from /lib64/libpthread.so.0 see the following:

(gdb) back
#0  0x00007f93ba2f254d in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007f93ba2eded1 in _L_lock_1093 () from /lib64/libpthread.so.0
#2  0x00007f93ba2ede72 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007f93b0d30eb9 in PR_Lock () from /lib64/libnspr4.so
#4  0x00007f93b15e540d in pk11_filterSlot () from /lib64/libnss3.so
#5  0x00007f93b15e544b in PK11_DoesMechanismFlag () from /lib64/libnss3.so
#6  0x00007f93b15bddfc in pk11_contextInitMessage.isra.1 () from /lib64/libnss3.so
#7  0x00007f93b15be769 in pk11_context_init () from /lib64/libnss3.so
#8  0x00007f93b15be92d in pk11_CreateNewContextInSlot () from /lib64/libnss3.so
#9  0x00007f93b15bea8f in PK11_CreateContextBySymKey () from /lib64/libnss3.so
#10 0x00007f93b1af10ae in ssl3_InitPendingContexts.isra.19 () from /lib64/libssl3.so
#11 0x00007f93b1af5707 in ssl3_InitPendingCipherSpecs () from /lib64/libssl3.so
#12 0x00007f93b1b15629 in ssl3_SendECDHClientKeyExchange () from /lib64/libssl3.so
#13 0x00007f93b1afacb3 in ssl3_SendClientSecondRound () from /lib64/libssl3.so
#14 0x00007f93b1afc6d6 in ssl3_HandleHandshakeMessage () from /lib64/libssl3.so
#15 0x00007f93b1aff8d3 in ssl3_HandleNonApplicationData () from /lib64/libssl3.so
#16 0x00007f93b1affe71 in ssl3_HandleRecord () from /lib64/libssl3.so
#17 0x00007f93b1b0147f in ssl3_GatherCompleteHandshake () from /lib64/libssl3.so
#18 0x00007f93b1b08eab in SSL_ForceHandshake () from /lib64/libssl3.so
#19 0x00007f93b21e0f73 in nss_connect_common () from /lib64/libcurl.so.4
#20 0x00007f93b21d7d8e in Curl_ssl_connect_nonblocking () from /lib64/libcurl.so.4
#21 0x00007f93b21ae7ae in https_connecting () from /lib64/libcurl.so.4
#22 0x00007f93b21d1728 in multi_runsingle () from /lib64/libcurl.so.4
#23 0x00007f93b21d2641 in curl_multi_perform () from /lib64/libcurl.so.4
#24 0x00007f93b21c9853 in curl_easy_perform () from /lib64/libcurl.so.4
#25 0x00007f93b24145dc in zif_curl_exec () from /opt/rh/rh-php72/root/usr/lib64/php/modules/curl.so
#26 0x000056288b5ad46a in execute_ex ()
#27 0x000056288b5ae5b3 in zend_execute ()
#28 0x000056288b505463 in zend_execute_scripts ()
#29 0x000056288b4a0fa0 in php_execute_script ()
#30 0x000056288b5b09b6 in do_cli ()
#31 0x000056288b35e5be in main ()

Comment 11 Greg Bowyer 2021-05-04 20:51:36 UTC

I have encountered this in our CI environment through SCL and git

git tries to get at https://github.com/kubernetes/apiserver which calls `git ls-remote` which calls the protocol handler `git-remote-https`

Ps -ef looks like this for me

build      1652  1619  0 20:14 ?        00:00:03 /builds/publish-oel7-atlas-bzl_out/output/external/go_sdk/bin/go get -d -- github.com/vdemeester/k8s-pkg-credentialprovider
build      1817  1652  0 20:14 ?        00:00:00 git ls-remote -q origin
build      1818  1817  0 20:14 ?        00:00:00 /opt/rh/rh-git227/root/usr/libexec/git-core/git-remote-https origin https://github.com/kubernetes/apiserver

Doing strace on this gives me a hang on the underyling futex

root@ip-10-185-93-3:~# strace -p 1818
strace: Process 1818 attached
futex(0x564e03e95620, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 1818 detached

GDB stack dumping this gives me a stack looking like the above

warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
0x00007fc04c02054d in __lll_lock_wait () from target:/lib64/libpthread.so.0
(gdb) bt
#0  0x00007fc04c02054d in __lll_lock_wait () from target:/lib64/libpthread.so.0
#1  0x00007fc04c01bed1 in _L_lock_1093 () from target:/lib64/libpthread.so.0
#2  0x00007fc04c01be72 in pthread_mutex_lock () from target:/lib64/libpthread.so.0
#3  0x00007fc04a176eb9 in PR_Lock () from target:/lib64/libnspr4.so
#4  0x00007fc04aa193dd in pk11_GetNewSession () from target:/lib64/libnss3.so
#5  0x00007fc04aa235fd in pk11_CreateSymKey () from target:/lib64/libnss3.so
#6  0x00007fc04aa2432f in PK11_SymKeyFromHandle () from target:/lib64/libnss3.so
#7  0x00007fc04aa243ef in PK11_GetWrapKey () from target:/lib64/libnss3.so
#8  0x00007fc04af42207 in ssl3_CacheWrappedSecret () from target:/lib64/libssl3.so
#9  0x00007fc04af453ba in ssl3_HandleHandshakeMessage () from target:/lib64/libssl3.so
#10 0x00007fc04af468d3 in ssl3_HandleNonApplicationData () from target:/lib64/libssl3.so
#11 0x00007fc04af46e71 in ssl3_HandleRecord () from target:/lib64/libssl3.so
#12 0x00007fc04af484bf in ssl3_GatherCompleteHandshake () from target:/lib64/libssl3.so
#13 0x00007fc04af4feeb in SSL_ForceHandshake () from target:/lib64/libssl3.so
#14 0x00007fc04c94d26c in nss_connect_common () from target:/opt/rh/httpd24/root/usr/lib64/libcurl-httpd24.so.4
#15 0x00007fc04c9491d6 in Curl_ssl_connect_nonblocking () from target:/opt/rh/httpd24/root/usr/lib64/libcurl-httpd24.so.4
#16 0x00007fc04c8f83f2 in https_connecting () from target:/opt/rh/httpd24/root/usr/lib64/libcurl-httpd24.so.4
#17 0x00007fc04c91950e in multi_runsingle () from target:/opt/rh/httpd24/root/usr/lib64/libcurl-httpd24.so.4
#18 0x00007fc04c91a661 in curl_multi_perform () from target:/opt/rh/httpd24/root/usr/lib64/libcurl-httpd24.so.4
#19 0x0000564e0350509f in step_active_slots ()
#20 0x0000564e0350513d in run_active_slot ()
#21 0x0000564e03505418 in run_one_slot ()
#22 0x0000564e03506869 in http_request ()
#23 0x0000564e0350717f in http_request_reauth ()
#24 0x0000564e0350118b in discover_refs ()
#25 0x0000564e03501d53 in cmd_main ()
#26 0x0000564e034ffc55 in main ()
(gdb) cont
Continuing.

Comment 12 Bob Relyea 2021-05-04 23:09:59 UTC

Hi Greg,

There are two known deadlocks in NSS. Once is quite easy to reproduce, the second isn't. The easy to reproduce one should be fixed in the latest 7.9.z and matches the traceback that Josef has. Your traceback is for the harder one to reproduce. I'm tracking the latter in bug 1909261.

If you need a fix immediately, contact your support person, otherwise expect a refresh this summer which should fix the problem.

BTW, if you see this bug closed, it's because the original customer confirmed that the current z stream build fixed their problem, 
bug 1909261 will close once we ship the fix for the issue you described.

bob

Comment 13 ashaya 2021-05-06 17:11:12 UTC

Hi,

I'm seeing this same stack in NSS 3.44. You can see php/curl is using nss 3.44 (at least I think it is) and I'm still getting same stack trace listed above.

#  php -i | grep SSL
SSL => Yes
SSL Version => NSS/3.44
core SSL => supported
extended SSL => supported
OpenSSL support => enabled
OpenSSL Library Version => OpenSSL 1.0.2k-fips  26 Jan 2017
OpenSSL Header Version => OpenSSL 1.0.2k  26 Jan 2017
Native OpenSSL support => enabled

# php -v
PHP 7.2.34 (cli) (built: Apr 28 2021 07:46:55) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.2.0, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.2.34, Copyright (c) 1999-2018, by Zend Technologies


# strace -p 2926
strace: Process 2926 attached
futex(0x55ba79e161e0, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 2926 detached
 <detached ...>

(gdb) bt
#0  0x00007fbbf22be54d in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007fbbf22b9ed1 in _L_lock_1093 () from /lib64/libpthread.so.0
#2  0x00007fbbf22b9e72 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007fbbe8938eb9 in PR_Lock () from /lib64/libnspr4.so
#4  0x00007fbbe91db3dd in pk11_GetNewSession () from /lib64/libnss3.so
#5  0x00007fbbe91e55fd in pk11_CreateSymKey () from /lib64/libnss3.so
#6  0x00007fbbe91e632f in PK11_SymKeyFromHandle () from /lib64/libnss3.so
#7  0x00007fbbe91e63ef in PK11_GetWrapKey () from /lib64/libnss3.so
#8  0x00007fbbe9704207 in ssl3_CacheWrappedSecret () from /lib64/libssl3.so
#9  0x00007fbbe97073ba in ssl3_HandleHandshakeMessage () from /lib64/libssl3.so
#10 0x00007fbbe97088d3 in ssl3_HandleNonApplicationData () from /lib64/libssl3.so
#11 0x00007fbbe9708e71 in ssl3_HandleRecord () from /lib64/libssl3.so
#12 0x00007fbbe970a4bf in ssl3_GatherCompleteHandshake () from /lib64/libssl3.so
#13 0x00007fbbe9711eeb in SSL_ForceHandshake () from /lib64/libssl3.so
#14 0x00007fbbe9de9f73 in nss_connect_common () from /lib64/libcurl.so.4
#15 0x00007fbbe9de0d8e in Curl_ssl_connect_nonblocking () from /lib64/libcurl.so.4
#16 0x00007fbbe9db77ae in https_connecting () from /lib64/libcurl.so.4
#17 0x00007fbbe9dda728 in multi_runsingle () from /lib64/libcurl.so.4
#18 0x00007fbbe9ddb641 in curl_multi_perform () from /lib64/libcurl.so.4
#19 0x00007fbbe9dd2853 in curl_easy_perform () from /lib64/libcurl.so.4
#20 0x00007fbbea01d5a8 in zif_curl_exec () from /opt/remi/php72/root/usr/lib64/php/modules/curl.so
#21 0x000055ba77cfab3f in ZEND_DO_FCALL_SPEC_RETVAL_UNUSED_HANDLER ()
#22 0x000055ba77d64728 in execute_ex ()
#23 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#24 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#25 0x000055ba77d64728 in execute_ex ()
#26 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#27 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#28 0x000055ba77d64728 in execute_ex ()
#29 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#30 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#31 0x000055ba77d64728 in execute_ex ()
#32 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#33 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#34 0x000055ba77d64728 in execute_ex ()
#35 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#36 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#37 0x000055ba77d64728 in execute_ex ()
#38 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#39 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#40 0x000055ba77d64728 in execute_ex ()
#41 0x00007fbbe0fbccc0 in nr_php_execute () at /home/hudson/workspace/php-release-agent/label/centos5-64-nrcamp/agent/php_execute.c:1329
#42 0x000055ba77cfaf3e in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER ()
#43 0x000055ba77d64728 in execute_ex ()

# php -r "print_r(curl_version());"
Array
(
    [version_number] => 466176
    [age] => 3
    [features] => 558781
    [ssl_version_number] => 0
    [version] => 7.29.0
    [host] => x86_64-redhat-linux-gnu
    [ssl_version] => NSS/3.44
    [libz_version] => 1.2.7
    [protocols] => Array
        (
            [0] => dict
            [1] => file
            [2] => ftp
            [3] => ftps
            [4] => gopher
            [5] => http
            [6] => https
            [7] => imap
            [8] => imaps
            [9] => ldap
            [10] => ldaps
            [11] => pop3
            [12] => pop3s
            [13] => rtsp
            [14] => scp
            [15] => sftp
            [16] => smtp
            [17] => smtps
            [18] => telnet
            [19] => tftp
        )

)

Comment 16 Bob Relyea 2021-06-23 22:31:13 UTC

Ooops this bug need zstream+, the pm_ack worked here.

Comment 29 errata-xmlrpc 2021-10-12 15:26:38 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (nss, nss-softokn, nss-util, and nspr bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:3793