126501 - SSL client dies in handshake code in NSS 3.4

Status: RESOLVED DUPLICATE of bug 126289

(NSS :: Libraries, defect, P1)

Description

[Julien Pierre]

Last night I ran another stress test on my Sun box with NSS 3.4 . I was not
using client auth this time. The client dumped core at 8:20am with the following
stack :
et@33 (l@102) terminated by signal ABRT (Abort)
re
Current function is PR_Assert
  495       abort();
(dbx) current thread: t@33
  [1] __sigprocmask(0x0, 0xfddf1210, 0x0, 0x0, 0x0, 0x0), at 0xfec39bf0
  [2] _resetsig(0xfec3c510, 0x0, 0x0, 0xfddf1d78, 0xfec4e000, 0x0), at 0xfec2e620
  [3] _sigon(0xfddf1d78, 0xfec55990, 0x6, 0xfddf12e4, 0xfddf1d78, 0xfddf1328),
at 0xfec2dd10
  [4] _thrp_kill(0x0, 0x21, 0x6, 0xfec4e000, 0x21, 0xfebba428), at 0xfec30e84
  [5] raise(0x6, 0x0, 0x0, 0xffffffff, 0xfebba394, 0xfee6b6dc), at 0xfeb49b08
  [6] abort(0xfebb6000, 0x3f, 0xfebbd99c, 0xfebb9c78, 0x7a, 0xfeb91c94), at
0xfeb35124
=>[7] PR_Assert(s = 0xff308044 "!ssl_HaveRecvBufLock(ss)", file = 0xff308060
"sslsecur.c", ln = 122), line 495 in "prlog.c"
  [8] ssl_Do1stHandshake(ss = 0x19a3b158), line 122 in "sslsecur.c"
  [9] ssl_SecureSend(ss = 0x19a3b158, buf = 0xb5578 "GET /index.html
HTTP/1.0\n\n", len = 26, flags = 0), line 1100 in "sslsecur.c"
  [10] ssl_Send(fd = 0x123f10, buf = 0xb5578, len = 26, flags = 0, timeout =
360000000U), line 1212 in "sslsock.c"
  [11] PR_Send(fd = 0x123f10, buf = 0xb5578, amount = 26, flags = 0, timeout =
360000000U), line 221 in "priometh.c"
  [12] SunRequest::send(this = 0x19a3b110, sock = 0x123f10), line 308 in
"request.cpp"
  [13] SunEngine::makeRequest(this = 0xfddf1b64, request = CLASS, server =
CLASS, ignoresenderror = 1), line 413 in "engine.cpp"
  [14] SunTest::run(this = 0x8df10), line 454 in "tests.cpp"
  [15] TestInstance::execute_test(this = 0x8dec0), line 152 in "tests.cpp"
  [16] thread_entry(arg = (nil)), line 1684 in "tests.cpp"
  [17] _pt_root(arg = 0xeec28), line 214 in "ptthread.c"
(dbx) 

This is very similar to the stack in defect 126289, which was an NSS 3.3.2 bug.
I'm not sure if there was a memory leak in this test or not. The core is over
400 MB but I don't know if that really says much. Next time I will run a script
in the background that will monitor each process' memory usage periodically
using pmap.

Comment 1

[Wan-Teh Chang]

The only difference of this stack from the stack in bug 126289
is that in that bug it is the assertion at sslsecur.c:123 that
failed:
        PORT_Assert( !ssl_HaveXmitBufLock(ss)   );

I will need to examine the core files to see who owns the
RecvBufLock and XmitBufLock when the assertions failed.

Comment 2

[Wan-Teh Chang]

This is from dbx on the core file.  Since both ss->gather->buf
and ss->sec->writeBuf look fine, this does NOT support my theory
that we ran out of memory when creating these buffers in
ssl_CreateSecurityInfo().

detected a multithreaded program
t@33 (l@102) terminated by signal ABRT (Abort)
0xfec39bf0: __sigprocmask+0x0008:       jmp     %o7 + 0x8
Current function is PR_Assert
  495       abort();
(/tools/ns/workshop-6.0u2/bin/../WS6U2/bin/sparcv9/dbx) up
Current function is ssl_Do1stHandshake
  124           PORT_Assert( !ssl_HaveRecvBufLock(ss)   );
(/tools/ns/workshop-6.0u2/bin/../WS6U2/bin/sparcv9/dbx) print ss
ss = 0x19a3b158
(/tools/ns/workshop-6.0u2/bin/../WS6U2/bin/sparcv9/dbx) print *ss
*ss = {
    fd                    = 0x123f10
    ops                   = 0xff31f2e4
    useSocks              = 0
    useSecurity           = 1U
    requestCertificate    = 0
    requireCertificate    = 2U
    handshakeAsClient     = 1U
    handshakeAsServer     = 0
    enableSSL2            = 1U
    enableSSL3            = 1U
    enableTLS             = 1U
    clientAuthRequested   = 0
    noCache               = 1U
    fdx                   = 0
    v2CompatibleHello     = 1U
    detectRollBack        = 1U
    firstHsDone           = 0
    recvdCloseNotify      = 0
    lastWriteBlocked      = 0
    TCPconnected          = 1U
    handshakeBegun        = 0
    delayDisabled         = 0
    version               = 0
    clientHelloVersion    = 0
    sec                   = 0x19a96c08
    url                   = 0x199c3758 "localhost"
    gather                = 0x19a967a0
    handshake             = (nil)
    nextHandshake         = (nil)
    securityHandshake     = 0xff2eb878 = &ssl2_BeginClientHandshake()
    saveBuf               = {
        buf   = (nil)
        len   = 0
        space = 0
    }
    pendingBuf            = {
        buf   = (nil)
        len   = 0
        space = 0
    }
    peerID                = (nil)
    ssl3                  = (nil)
    cipherSpecs           = (nil)
    sizeCipherSpecs       = 0
    preferredCipher       = (nil)
    serverCerts           = (
{
        serverCert      = (nil)
        serverCertChain = (nil)
        serverKey       = (nil)
        serverKeyBits   = 0
    }{
        serverCert      = (nil)
        serverCertChain = (nil)
        serverKey       = (nil)
        serverKeyBits   = 0
    }{
        serverCert      = (nil)
        serverCertChain = (nil)
        serverKey       = (nil)
        serverKeyBits   = 0
    }{
        serverCert      = (nil)
        serverCertChain = (nil)
        serverKey       = (nil)
        serverKeyBits   = 0
    }
)
    stepDownKeyPair       = (nil)
    authCertificate       = 0x2a3a8 = &`httptest`engine.cpp`certcallback(void
*arg, struct PRFileDesc *fd, PRBool checksig, PRBool isServer)
    authCertificateArg    = 0x857b0
    getClientAuthData     = (nil)
    getClientAuthDataArg  = (nil)
    handleBadCert         = (nil)
    badCertArg            = (nil)
    handshakeCallback     = (nil)
    handshakeCallbackData = (nil)
    pkcs11PinArg          = (nil)
    rTimeout              = 360000000U
    wTimeout              = 360000000U
    cTimeout              = 360000000U
    recvLock              = 0x19b06b80
    sendLock              = 0x19b06be0
    recvBufLock           = 0x19b06a90
    xmitBufLock           = 0x19b06b08
    firstHandshakeLock    = 0x19a3b2c0
    ssl3HandshakeLock     = 0x19a3b338
    specLock              = 0x199c40e0
    dbHandle              = 0x857b0
    writerThread          = 0xeec28
    shutdownHow           = 0
    allowedByPolicy       = 222U
    maybeAllowedByPolicy  = 222U
    chosenPreference      = 255U
    handshaking           = sslHandshakingAsClient
    cipherSuites          = (
{
        cipher_suite = 57U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 56U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 53U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 30U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 102U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 51U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 50U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 4U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 5U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 47U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 22U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 19U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 65279U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 10U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 29U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 21U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 18U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }{
        cipher_suite = 65278U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 9U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 100U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 98U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 3U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 6U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 28U
        policy       = 1U
        enabled      = 1U
        isPresent    = 0
    }{
        cipher_suite = 1U
        policy       = 1U
        enabled      = 0
        isPresent    = 0
    }
)
}
(/tools/ns/workshop-6.0u2/bin/../WS6U2/bin/sparcv9/dbx) print ss->sec
ss->sec = 0x19a96c08
(/tools/ns/workshop-6.0u2/bin/../WS6U2/bin/sparcv9/dbx) print *ss->sec
*ss->sec = {
    send          = 0xff2e4b40 = &`libssl3.so`sslcon.c`ssl2_SendClear(struct
sslSocketStr *ss, const PRUint8 *in, PRInt32 len, PRInt32 flags)
    isServer      = 0
    writeBuf      = {
        buf   = 0x19a35e90 ""
        len   = 0
        space = 4096U
    }
    cipherType    = 0
    keyBits       = 0
    secretKeyBits = 0
    localCert     = (nil)
    peerCert      = (nil)
    peerKey       = (nil)
    authAlgorithm = ssl_sign_null
    authKeyBits   = 0
    keaType       = ssl_kea_null
    keaKeyBits    = 0
    cache         = (nil)
    uncache       = (nil)
    sendSequence  = 0
    rcvSequence   = 0
    hash          = (nil)
    hashcx        = (nil)
    sendSecret    = {
        type = siBuffer
        data = (nil)
        len  = 0
    }
    rcvSecret     = {
        type = siBuffer
        data = (nil)
        len  = 0
    }
    readcx        = (nil)
    writecx       = (nil)
    enc           = (nil)
    dec           = (nil)
    destroy       = (nil)
    blockShift    = 0
    blockSize     = 1
    ci            = {
        sendBuf            = {
            buf   = (nil)
            len   = 0
            space = 0
        }
        peer               = {
            _S6_un = {
                _S6_u8  = ""
                _S6_u16 = (0, 0, 0, 0, 0, 0, 0, 0)
                _S6_u32 = (0, 0, 0, 0)
                _S6_u64 = (0, 0)
            }
        }
        port               = 0
        sid                = (nil)
        elements           = '\0'
        requiredElements   = '\0'
        sentElements       = '\0'
        sentFinished       = '\0'
        serverChallengeLen = 0
        authType           = '\0'
        clientChallenge    = ""
        connectionID       = ""
        serverChallenge    = ""
        readKey            = ""
        writeKey           = ""
        keySize            = 0
    }
}
(/tools/ns/workshop-6.0u2/bin/../WS6U2/bin/sparcv9/dbx) print *ss->gather 
*ss->gather = {
    state         = 0
    buf           = {
        buf   = 0x19a34e88 ""
        len   = 0
        space = 4096U
    }
    offset        = 0
    remainder     = 0
    count         = 0
    recordLen     = 0
    recordPadding = 0
    recordOffset  = 0
    encrypted     = 0
    readOffset    = 0
    writeOffset   = 0
    inbuf         = {
        buf   = (nil)
        len   = 0
        space = 0
    }
    hdr           = ""
}

Comment 3

[Wan-Teh Chang]

One more thing about the core file: the value of 'loopCount' in
ssl_Do1stHandshake() is 0, which means the monitor's lock count
was already non-zero when the function was entered.

ss->recvBufLock->entryCount is 1.

I am now at a loss.  The only explanation I can come up with is
that ssl_CreateSecurityInfo was called at least twice before we
called ssl_Do1stHandshake(), and for some reason the first call
to ssl_CreateSecurityInfo failed but the second call succeeded.
This seems unlikely though.

Nelson, for a normal SSL client, does it call ssl_CreateSecurityInfo
twice before it gets to call ssl_Do1stHandshake()?

Comment 4

[Nelson Bolyard (seldom reads bugmail)]

I think the hypothesis that that ssl_CreateSecurityInfo was called at 
least twice is viable.  You'll find calls to ssl_CreateSecurityInfo in 
many places in libssl.  The function doesn't allocate another SecurityInfo 
struct if one is already allocated, so it doesn't hurt to call it many times.  
Apparently my predecssors had a lot of problems with references to null sec 
pointers, so they puts calls to the Create function all over the place.

I'm working on a patch now to make the SecurityInfo struct be part of the
sslSocket str, so that it will be allocated with the ssl socket.  Besides
reducing the number of calls to malloc and free slightly, it will also 
greatly reduce the number of pointer indirections required to access members
of this struct.  e.g. ss->sec.foo instead of ss->sec->foo.  I will attach
the patch here soon.

Comment 5

[Julien Pierre]

This is the same bug as 126289, but on a different NSS version. Marking this one
duplicate.

*** This bug has been marked as a duplicate of 126289 ***