Last Comment Bug 452751 - Slot leak in PK11_FindSlotsByNames
: Slot leak in PK11_FindSlotsByNames
Status: RESOLVED FIXED
:
Product: NSS
Classification: Components
Component: Libraries (show other bugs)
: 3.12
: All All
: P2 normal (vote)
: 3.12.2
Assigned To: Julien Pierre
:
Mentors:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2008-08-29 02:51 PDT by Ludovic Rousseau
Modified: 2008-09-25 17:02 PDT (History)
2 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---


Attachments
Plug slot reference leak (929 bytes, patch)
2008-09-25 16:34 PDT, Julien Pierre
nelson: review+
Details | Diff | Splinter Review

Description Ludovic Rousseau 2008-08-29 02:51:01 PDT
User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; fr; rv:1.9.0.1) Gecko/2008070206 Firefox/3.0.1
Build Identifier: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; fr; rv:1.9.0.1) Gecko/2008070206 Firefox/3.0.1

When using a PKCS#11 token The PKCS#11 sequence used by firefox (and thunderbird) is something like:

 C_Initialize
 C_*
 C_Finalize
 C_Initialize

The latest C_Initialize has no corresponding C_Initialize so resources allocated by the PKCS#11 token are not correctly released since no C_Initialize is called.

Reproducible: Always

Steps to Reproduce:
1. install a PKCS#11 spy like pkcs11-spy from OpenSC (http://www.opensc-project.org/opensc/browser/trunk/src/pkcs11/pkcs11-spy.c)
2. configure pkcs11-spy by defining the PKCS11SPY env variable to a real PKCS#11 and PKCS11SPY_OUTPUT to a trace filename
3. configure Firefox to use the pkcs11-spy as a PKCS#11 token
4. quit firefox
5. look at the PKCS#11 trace generated by pkcs11-spy
Actual Results:  
*************** OpenSC PKCS#11 spy *****************
Loaded: "/usr/lib/pkcs11/xxx.so"


0: C_GetFunctionList
Returned:  0 CKR_OK


1: C_Initialize
[in] pInitArgs = 0xb6e89d6c
Returned:  9 CKR_NEED_TO_CREATE_THREADS


2: C_Initialize
[in] pInitArgs = (nil)
Returned:  0 CKR_OK


3: C_GetInfo
      cryptokiVersion:         2.1
      manufacturerID:         'xxxxxxx                         '
      flags:                   0
      libraryDescription:     'PKCS#11 Cryptoki                '
      libraryVersion:          5.1
Returned:  0 CKR_OK

[...]

262: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo: 
      slotID:                  1
      state:                  '           CKS_RO_USER_FUNCTIONS'
      flags:                   4
        CKF_SERIAL_SESSION               
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK


263: C_Finalize
Returned:  0 CKR_OK


264: C_Initialize
[in] pInitArgs = (nil)
Returned:  0 CKR_OK

Expected Results:  
*************** OpenSC PKCS#11 spy *****************
Loaded: "/usr/lib/pkcs11/xxx.so"


0: C_GetFunctionList
Returned:  0 CKR_OK


1: C_Initialize
[in] pInitArgs = 0xb6e89d6c
Returned:  9 CKR_NEED_TO_CREATE_THREADS


2: C_Initialize
[in] pInitArgs = (nil)
Returned:  0 CKR_OK


3: C_GetInfo
      cryptokiVersion:         2.1
      manufacturerID:         'xxxxxxx                         '
      flags:                   0
      libraryDescription:     'PKCS#11 Cryptoki                '
      libraryVersion:          5.1
Returned:  0 CKR_OK

[...]

262: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo: 
      slotID:                  1
      state:                  '           CKS_RO_USER_FUNCTIONS'
      flags:                   4
        CKF_SERIAL_SESSION               
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK


263: C_Finalize
Returned:  0 CKR_OK

Without the last C_Initialize call.
Comment 1 Kai Engert (:kaie) 2008-09-09 23:23:43 PDT
PSM does not call C_Initialize, I believe this is an NSS bug.
Comment 2 Nelson Bolyard (seldom reads bugmail) 2008-09-10 08:51:11 PDT
Comment 0 says:
> The latest C_Initialize has no corresponding C_Initialize 
I presume the writer actually meant
  The latest C_Initialize has no corresponding /C_Finalize/

Kai, I doubt that this is an NSS bug.

PSM calls NSS_Init* which calls C_Initialize.  PSM also has the ability to 
load new PKCS#11 modules in the running process by calling some NSS function 
that does so. (I'd have to look for the NSS function name by which PSM does 
that).  Doing so calls C_Initialize on the newly loaded module.  

PSM also calls NSS_Shutdown, which calls C_Finalize on all loaded modules.

IMO, a likely explanation for this is that during shutdown, after PSM has 
called NSS_Shutdown, something causes PSM to call NSS_Init* again.
Comment 3 Ludovic Rousseau 2008-09-10 09:39:34 PDT
(In reply to comment #2)
> Comment 0 says:
> > The latest C_Initialize has no corresponding C_Initialize 
> I presume the writer actually meant
>   The latest C_Initialize has no corresponding /C_Finalize/

Exactly :-)
 
> IMO, a likely explanation for this is that during shutdown, after PSM has 
> called NSS_Shutdown, something causes PSM to call NSS_Init* again.

And the same something does not call NSS_Shutdown before Firefox exists?

How can I trace the PSM and/or NSS calls?

The bug is present on Linux and Mac. I have not checked on Windows but I guess it is also present.
Comment 4 Nelson Bolyard (seldom reads bugmail) 2008-09-10 10:18:05 PDT
> How can I trace the PSM and/or NSS calls?

truss, maybe?  :)

I suggest you set debugger breakpoints in your module's C_Initialize and C_Finalize functions, and get stack backtraces on each hit.  There won't
be many.
Comment 5 Ludovic Rousseau 2008-09-15 06:31:12 PDT
I added break points and discovered the source of the problem in file security/nss/lib/pk11wrap/pk11util.c function SECMOD_CancelWait()

/*
 * This function "wakes up" WaitForAnyTokenEvent. It's a pretty drastic
 * function, possibly bringing down the pkcs #11 module in question. This
 * should be OK because 1) it does reinitialize, and 2) it should only be
 * called when we are on our way to tear the whole system down anyway.
 */
SECStatus
SECMOD_CancelWait(SECMODModule *mod)
{
    unsigned long controlMask = mod->evControlMask;
    SECStatus rv = SECSuccess;
    CK_RV crv;

    PZ_Lock(mod->refLock);
    mod->evControlMask |= SECMOD_END_WAIT;
    controlMask = mod->evControlMask;
    if (controlMask & SECMOD_WAIT_PKCS11_EVENT) {
        if (!pk11_getFinalizeModulesOption()) {
            /* can't get here unless pk11_getFinalizeModulesOption is set */
            PORT_Assert(0);
            PORT_SetError(SEC_ERROR_LIBRARY_FAILURE);
            rv = SECFailure;
            goto loser;
        }
    /* NOTE: this call will drop all transient keys, in progress
     * operations, and any authentication. This is the only documented
     * way to get WaitForSlotEvent to return. Also note: for non-thread
     * safe tokens, we need to hold the module lock, this is not yet at
     * system shutdown/startup time, so we need to protect these calls */
    crv = PK11_GETTAB(mod)->C_Finalize(NULL);
    /* ok, we slammed the module down, now we need to reinit it in case
     * we intend to use it again */
    if (CKR_OK == crv) {
            PRBool alreadyLoaded;
        secmod_ModuleInit(mod, &alreadyLoaded);
    } else {
        /* Finalized failed for some reason,  notify the application
         * so maybe it has a prayer of recovering... */
        PORT_SetError(PK11_MapError(crv));
        rv = SECFailure;
    }
    } else if (controlMask & SECMOD_WAIT_SIMULATED_EVENT) {
    mod->evControlMask &= ~SECMOD_WAIT_SIMULATED_EVENT;
                /* Simulated events will eventually timeout
                 * and wake up in the loop */
    }
loser:
    PZ_Unlock(mod->refLock);
    return rv;
}


secmod_ModuleInit() is called after C_Finalize() and this will call C_Initialize.

So it looks that _by design_ the NSS lib is doing the C_Finalize/C_Initialize dance.

Maybe SECMOD_CancelWait() could have an extra parameter to indicate that Firefox is exiting and that C_Initialize should _not_ be called?

SECMOD_CancelWait() is called from (firefox) security/manager/ssl/src/nsSmartCardMonitor.cpp function SmartCardMonitoringThread::Stop()
Comment 6 Ludovic Rousseau 2008-09-18 05:42:12 PDT
I also note that if I start Firefox _without_ a smart card reader connected then when I exit Firefox I have this backtrace:

6: C_Finalize

Breakpoint 2, C_Finalize (pReserved=0x0) at Pkcs2Std.cpp:8946
(gdb) bt
#0  C_Finalize (pReserved=0x0) at Pkcs2Std.cpp:8946
#1  0xb2ecd511 in C_Finalize () from /usr/lib/pkcs11-spy.so
#2  0xb6e0693a in SECMOD_UnloadModule (mod=0x0) at pk11load.c:472
#3  0xb6e18a27 in SECMOD_SlotDestroyModule (module=0xb372a010, fromSlot=0)
    at pk11util.c:808
#4  0xb6e18aba in SECMOD_DestroyModule (module=0xb372a010) at pk11util.c:769
#5  0xb6e18b2c in SECMOD_DestroyModuleListElement (element=0xb3705250)
    at pk11util.c:825
#6  0xb6e18b69 in SECMOD_DestroyModuleList (list=0xb3705238) at pk11util.c:841
#7  0xb6e1956c in SECMOD_Shutdown () at pk11util.c:99
#8  0xb6dee7b3 in NSS_Shutdown () at nssinit.c:896
#9  0xb7718c98 in nsNSSComponent::ShutdownNSS (this=0xb7c4bc80)
    at nsNSSComponent.cpp:1690
#10 0xb7718d14 in nsNSSComponent::DoProfileBeforeChange (this=0xb7c4bc80,
    aSubject=0xae749838) at nsNSSComponent.cpp:2388
#11 0xb7718eeb in nsNSSComponent::Observe (this=0xb7c4bc80,
    aSubject=0xae749838, aTopic=0xb791b811 "profile-before-change",
    someData=0xb791ba2c) at nsNSSComponent.cpp:1972
#12 0xb78980bc in nsObserverList::NotifyObservers (this=0xb3752174,
    aSubject=0xae749838, aTopic=0xb791b811 "profile-before-change",
    someData=0xb791ba2c) at nsObserverList.cpp:128
#13 0xb789838a in nsObserverService::NotifyObservers (this=0xb7cb84f0,
    aSubject=0xae749838, aTopic=0xb791b811 "profile-before-change",
    someData=0xb791ba2c) at nsObserverService.cpp:181
#14 0xb7171bd9 in nsXREDirProvider::DoShutdown (this=0xbf827584)
    at nsXREDirProvider.cpp:855
#15 0xb716d7b9 in ~ScopedXPCOMStartup (this=0xbf827744) at nsAppRunner.cpp:915
#16 0xb716fb3c in XRE_main (argc=3, argv=0xbf828674, aAppData=0xb7c1eb40)
    at nsAppRunner.cpp:3223
#17 0x080490a9 in main (argc=3, argv=0xbf828674) at nsXULStub.cpp:421
(gdb)

And no C_initialize() is made after that.


When I have a smart card reader connected but NO card in the reader I have the sequence:

*************** OpenSC PKCS#11 spy *****************
Loaded: "/usr/lib/pkcs11/libgclib.so"


0: C_GetFunctionList
Returned:  0 CKR_OK


1: C_Initialize
Returned:  9 CKR_NEED_TO_CREATE_THREADS


2: C_Initialize
Returned:  0 CKR_OK


3: C_GetInfo
      cryptokiVersion:         2.1
      manufacturerID:         'Gemplus                         '
      flags:                   0
      libraryDescription:     'PKCS#11 Cryptoki Multiplexer    '
      libraryVersion:          5.1
Returned:  0 CKR_OK


4: C_GetSlotList
[in] tokenPresent = 0x0
[out] pSlotList:
Count is 1
[out] *pulCount = 0x1
Returned:  0 CKR_OK


5: C_GetSlotList
[in] tokenPresent = 0x0
[out] pSlotList:
Slot 1
[out] *pulCount = 0x1
Returned:  0 CKR_OK


6: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
      slotDescription:        'Gemplus GemPC Twin 00 00        '
                              '                                '
      manufacturerID:         'Gemplus                         '
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      flags:                   6
        CKF_REMOVABLE_DEVICE
        CKF_HW_SLOT
Returned:  0 CKR_OK


7: C_FindObjectsInit
[in] hSession = 0x0
[in] pTemplate[1]:
    CKA_CLASS             CKO_NETSCAPE_BUILTIN_ROOT_LIST
Returned:  179 CKR_SESSION_HANDLE_INVALID


8: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
      slotDescription:        'Gemplus GemPC Twin 00 00        '
                              '                                '
      manufacturerID:         'Gemplus                         '
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      flags:                   6
        CKF_REMOVABLE_DEVICE
        CKF_HW_SLOT
Returned:  0 CKR_OK


9: C_WaitForSlotEvent


10: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
      slotDescription:        'Gemplus GemPC Twin 00 00        '
                              '                                '
      manufacturerID:         'Gemplus                         '
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      flags:                   6
        CKF_REMOVABLE_DEVICE
        CKF_HW_SLOT
Returned:  0 CKR_OK


11: C_Finalize
Returned:  400 CKR_CRYPTOKI_NOT_INITIALIZED
Returned:  0 CKR_OK


*************** OpenSC PKCS#11 spy *****************
Loaded: "/usr/lib/pkcs11/libgclib.so"


12: C_Initialize
Returned:  0 CKR_OK


13: C_CloseAllSessions
[in] slotID = 0x1
Returned:  0 CKR_OK


14: C_Finalize
Returned:  0 CKR_OK

I have the C_Finalize, C_Initialize dance and then followed by C_CloseAllSessions and C_Finalize. This sequence is correct (even if not optimal when firefox is exiting).

The C_Finalize, C_Initialize are called from SECMOD_CancelWait() as seen previously.

The C_CloseAllSessions() is called from:
(gdb) bt
#0  C_CloseAllSessions (slotID=1) at Pkcs2Std.cpp:11417
#1  0xb3890bf7 in C_CloseAllSessions () from /usr/lib/pkcs11-spy.so
#2  0xb6daa409 in PK11_DestroySlot (slot=0x1) at pk11slot.c:431
#3  0xb6daa4b2 in PK11_FreeSlot (slot=0xb3681000) at pk11slot.c:461
#4  0xb6dacaf3 in SECMOD_DestroyModule (module=0xb362a010) at pk11util.c:779
#5  0xb6dacb2c in SECMOD_DestroyModuleListElement (element=0xb3605250)
    at pk11util.c:825
#6  0xb6dacb69 in SECMOD_DestroyModuleList (list=0xb3605238) at pk11util.c:841
#7  0xb6dad56c in SECMOD_Shutdown () at pk11util.c:99
#8  0xb6d827b3 in NSS_Shutdown () at nssinit.c:896
#9  0xb76acc98 in nsNSSComponent::ShutdownNSS (this=0xb7b4bc80)
    at nsNSSComponent.cpp:1690
#10 0xb76acd14 in nsNSSComponent::DoProfileBeforeChange (this=0xb7b4bc80,
    aSubject=0xaee59838) at nsNSSComponent.cpp:2388
#11 0xb76aceeb in nsNSSComponent::Observe (this=0xb7b4bc80,
    aSubject=0xaee59838, aTopic=0xb78af811 "profile-before-change",
    someData=0xb78afa2c) at nsNSSComponent.cpp:1972
#12 0xb782c0bc in nsObserverList::NotifyObservers (this=0xb3653174,
    aSubject=0xaee59838, aTopic=0xb78af811 "profile-before-change",
    someData=0xb78afa2c) at nsObserverList.cpp:128
#13 0xb782c38a in nsObserverService::NotifyObservers (this=0xb7bb84f0,
    aSubject=0xaee59838, aTopic=0xb78af811 "profile-before-change",
    someData=0xb78afa2c) at nsObserverService.cpp:181
#14 0xb7105bd9 in nsXREDirProvider::DoShutdown (this=0xbffe0d04)
    at nsXREDirProvider.cpp:855
#15 0xb71017b9 in ~ScopedXPCOMStartup (this=0xbffe0ec4) at nsAppRunner.cpp:915
#16 0xb7103b3c in XRE_main (argc=3, argv=0xbffe1df4, aAppData=0xb7b1eb40)
    at nsAppRunner.cpp:3223
#17 0x080490a9 in main (argc=3, argv=0xbffe1df4) at nsXULStub.cpp:421
(gdb)

and C_Finalize() is called from:
(gdb) bt
#0  C_Finalize (pReserved=0x0) at Pkcs2Std.cpp:8946
#1  0xb3893511 in C_Finalize () from /usr/lib/pkcs11-spy.so
#2  0xb6d9a93a in SECMOD_UnloadModule (mod=0x0) at pk11load.c:472
#3  0xb6daca27 in SECMOD_SlotDestroyModule (module=0xb362a010, fromSlot=1)
    at pk11util.c:808
#4  0xb6daa46d in PK11_DestroySlot (slot=0xb3681000) at pk11slot.c:448
#5  0xb6daa4b2 in PK11_FreeSlot (slot=0xb3681000) at pk11slot.c:461
#6  0xb6dacaf3 in SECMOD_DestroyModule (module=0xb362a010) at pk11util.c:779
#7  0xb6dacb2c in SECMOD_DestroyModuleListElement (element=0xb3605250)
    at pk11util.c:825
#8  0xb6dacb69 in SECMOD_DestroyModuleList (list=0xb3605238) at pk11util.c:841
#9  0xb6dad56c in SECMOD_Shutdown () at pk11util.c:99
#10 0xb6d827b3 in NSS_Shutdown () at nssinit.c:896
#11 0xb76acc98 in nsNSSComponent::ShutdownNSS (this=0xb7b4bc80)
    at nsNSSComponent.cpp:1690
#12 0xb76acd14 in nsNSSComponent::DoProfileBeforeChange (this=0xb7b4bc80,
    aSubject=0xaee59838) at nsNSSComponent.cpp:2388
#13 0xb76aceeb in nsNSSComponent::Observe (this=0xb7b4bc80,
    aSubject=0xaee59838, aTopic=0xb78af811 "profile-before-change",
    someData=0xb78afa2c) at nsNSSComponent.cpp:1972
#14 0xb782c0bc in nsObserverList::NotifyObservers (this=0xb3653174,
    aSubject=0xaee59838, aTopic=0xb78af811 "profile-before-change",
    someData=0xb78afa2c) at nsObserverList.cpp:128
#15 0xb782c38a in nsObserverService::NotifyObservers (this=0xb7bb84f0,
    aSubject=0xaee59838, aTopic=0xb78af811 "profile-before-change",
    someData=0xb78afa2c) at nsObserverService.cpp:181
#16 0xb7105bd9 in nsXREDirProvider::DoShutdown (this=0xbffe0d04)
    at nsXREDirProvider.cpp:855
#17 0xb71017b9 in ~ScopedXPCOMStartup (this=0xbffe0ec4) at nsAppRunner.cpp:915
#18 0xb7103b3c in XRE_main (argc=3, argv=0xbffe1df4, aAppData=0xb7b1eb40)
    at nsAppRunner.cpp:3223
#19 0x080490a9 in main (argc=3, argv=0xbffe1df4) at nsXULStub.cpp:421
(gdb)

The function PK11_DestroySlot() from ./security/nss/lib/pk11wrap/pk11slot.c is correctly doing his job here.

The question now is: what is happening when a card is in the reader?
Comment 7 Ludovic Rousseau 2008-09-18 08:32:13 PDT
I instrumented the functions PK11_ReferenceSlot() and PK11_FreeSlot() in ./mozilla/security/nss/lib/pk11wrap/pk11slot.c

It looks like a call to PK11_FreeSlot() is missing (when a card is present in the reader)

Starting program: /usr/lib/iceweasel/firefox-bin -a firefox
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
Executing new program: /usr/lib/xulrunner-1.9/xulrunner-stub
[Thread debugging using libthread_db enabled]
[New Thread 0xb7cca6c0 (LWP 14663)]
[New Thread 0xb5affb90 (LWP 14669)]
[New Thread 0xb51ffb90 (LWP 14670)]
[New Thread 0xb48fdb90 (LWP 14671)]
[Thread 0xb48fdb90 (LWP 14671) exited]
[New Thread 0xb40fdb90 (LWP 14673)]
[Thread 0xb40fdb90 (LWP 14673) exited]
[New Thread 0xb40fdb90 (LWP 14674)]
[New Thread 0xb48fdb90 (LWP 14675)]
[New Thread 0xb35ffb90 (LWP 14676)]
POUET reference (null) 1 -> 2
POUET reference (null) 2 -> 3
POUET reference (null) 3 -> 4
POUET reference (null) 4 -> 5
POUET reference (null) 5 -> 6
POUET reference (null) 6 -> 7
POUET reference (null) 7 -> 8
POUET reference (null) 8 -> 9
POUET reference (null) 9 -> 10
POUET reference (null) 10 -> 11
POUET reference (null) 11 -> 12
POUET reference (null) 12 -> 13


*************** OpenSC PKCS#11 spy *****************
Loaded: "/usr/lib/pkcs11/libgclib.so"


0: C_GetFunctionList
Returned:  0 CKR_OK


1: C_Initialize
Returned:  9 CKR_NEED_TO_CREATE_THREADS


2: C_Initialize
Returned:  0 CKR_OK


3: C_GetInfo
Returned:  0 CKR_OK


4: C_GetSlotList
[in] tokenPresent = 0x0
[out] pSlotList:
Count is 1
[out] *pulCount = 0x1
Returned:  0 CKR_OK


5: C_GetSlotList
[in] tokenPresent = 0x0
[out] pSlotList:
Slot 1
[out] *pulCount = 0x1
Returned:  0 CKR_OK


6: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
Returned:  0 CKR_OK


7: C_GetTokenInfo
[in] slotID = 0x1
[out] pInfo:
Returned:  0 CKR_OK


8: C_GetMechanismList
[in] slotID = 0x1
[out] pMechanismList[7]:
Count is 7
Returned:  0 CKR_OK


9: C_GetMechanismList
[in] slotID = 0x1
[out] pMechanismList[7]:
 CKM_RSA_PKCS
 CKM_RSA_PKCS_KEY_PAIR_GEN
 CKM_MD5_RSA_PKCS
 CKM_SHA1_RSA_PKCS
 CKM_SHA_1
 Unknown Mechanism (00000250)
 CKM_MD5
Returned:  0 CKR_OK


10: C_OpenSession
[in] slotID = 0x1
[in] flags = 0x4
pApplication=0xb3681000
Notify=0xb6dd24c9
[out] *phSession = 0x1
Returned:  0 CKR_OK
POUET reference (null) 13 -> 14


11: C_GenerateRandom
[in] hSession = 0x1
[out] RandomData[ulRandomLen] [size : 0x20 (32)]
    FEFD632B 6D46662F D63FBBA7 C9DF5AA9 8653971B 40226564 B6D976E4 38B13A0E
Returned:  0 CKR_OK


12: C_SeedRandom
[in] hSession = 0x1
[in] pSeed[ulSeedLen] [size : 0x20 (32)]
    BF7F5103 1D220463 6ACED507 8D0F9FB6 A58C2B68 38A557D2 C26F62F5 ED39F504
Returned:  0 CKR_OK
POUET free (null) 14 -> 13


13: C_FindObjectsInit
[in] hSession = 0x1
[in] pTemplate[1]:
    CKA_CLASS             CKO_NETSCAPE_BUILTIN_ROOT_LIST
Returned:  0 CKR_OK


14: C_FindObjects
[in] hSession = 0x1
[in] ulMaxObjectCount = 0x1
[out] ulObjectCount = 0x0
Returned:  0 CKR_OK


15: C_FindObjectsFinal
[in] hSession = 0x1
Returned:  0 CKR_OK


16: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
      slotDescription:        'Gemplus GemPC Twin 00 00        '
                              '                                '
      manufacturerID:         'Gemplus                         '
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT
        CKF_REMOVABLE_DEVICE
        CKF_HW_SLOT
Returned:  0 CKR_OK


17: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo:
      slotID:                  1
      state:                  '           CKS_RO_PUBLIC_SESSION'
      flags:                   4
        CKF_SERIAL_SESSION
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK
POUET free /home/lroussea/.mozilla/firefox/uthb28d9.default/libnssckbi.so 1 -> 0
POUET destroy /home/lroussea/.mozilla/firefox/uthb28d9.default/libnssckbi.so
[New Thread 0xb1591b90 (LWP 14685)]
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 1 -> 2
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2


18: C_WaitForSlotEvent
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
[New Thread 0xb0bffb90 (LWP 14686)]
[Thread 0xb40fdb90 (LWP 14674) exited]
[New Thread 0xb40fdb90 (LWP 14687)]
POUET reference (null) 13 -> 14
POUET reference (null) 1 -> 2
POUET free (null) 2 -> 1


19: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo:
      slotID:                  1
      state:                  '           CKS_RO_PUBLIC_SESSION'
      flags:                   4
        CKF_SERIAL_SESSION
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET reference (null) 1 -> 2
POUET free (null) 2 -> 1
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
[New Thread 0xaf9ffb90 (LWP 14688)]
POUET reference (null) 13 -> 14


20: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
      slotDescription:        'Gemplus GemPC Twin 00 00        '
                              '                                '
      manufacturerID:         'Gemplus                         '
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT
        CKF_REMOVABLE_DEVICE
        CKF_HW_SLOT
Returned:  0 CKR_OK


21: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo:
      slotID:                  1
      state:                  '           CKS_RO_PUBLIC_SESSION'
      flags:                   4
        CKF_SERIAL_SESSION
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK
POUET reference (null) 1 -> 2
POUET free (null) 2 -> 1
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET reference (null) 1 -> 2
POUET free (null) 2 -> 1
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 1 -> 2
POUET reference (null) 2 -> 3
POUET free (null) 3 -> 2
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14


22: C_GetSlotInfo
[in] slotID = 0x1
[out] pInfo:
      slotDescription:        'Gemplus GemPC Twin 00 00        '
                              '                                '
      manufacturerID:         'Gemplus                         '
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT
        CKF_REMOVABLE_DEVICE
        CKF_HW_SLOT
Returned:  0 CKR_OK


23: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo:
      slotID:                  1
      state:                  '           CKS_RO_PUBLIC_SESSION'
      flags:                   4
        CKF_SERIAL_SESSION
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK
POUET reference (null) 2 -> 3
POUET free (null) 3 -> 2


24: C_GetSessionInfo
[in] hSession = 0x1
[out] pInfo:
      slotID:                  1
      state:                  '           CKS_RO_PUBLIC_SESSION'
      flags:                   4
        CKF_SERIAL_SESSION
      ulDeviceError:           ffff9000
Returned:  0 CKR_OK
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET reference (null) 2 -> 3
POUET free (null) 3 -> 2
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET reference (null) 2 -> 3
POUET free (null) 3 -> 2
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET reference (null) 2 -> 3
POUET free (null) 3 -> 2
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2
POUET reference (null) 14 -> 15
POUET free (null) 15 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
POUET reference (null) 13 -> 14
POUET free (null) 14 -> 13
[Thread 0xb48fdb90 (LWP 14675) exited]
[Thread 0xb35ffb90 (LWP 14676) exited]
[Thread 0xaf9ffb90 (LWP 14688) exited]
[Thread 0xb5affb90 (LWP 14669) exited]
POUET free (null) 2 -> 1
[Thread 0xb40fdb90 (LWP 14687) exited]


25: C_Finalize
Returned:  400 CKR_CRYPTOKI_NOT_INITIALIZED
Returned:  0 CKR_OK


*************** OpenSC PKCS#11 spy *****************
Loaded: "/usr/lib/pkcs11/libgclib.so"


26: C_Initialize
Returned:  0 CKR_OK
[Thread 0xb1591b90 (LWP 14685) exited]
POUET free /usr/lib/iceweasel/libnssckbi.so 1 -> 0
POUET destroy /usr/lib/iceweasel/libnssckbi.so
POUET free (null) 13 -> 12
POUET free (null) 12 -> 11
POUET free (null) 11 -> 10
POUET free (null) 10 -> 9
POUET free (null) 9 -> 8
POUET free (null) 8 -> 7
POUET free (null) 7 -> 6
POUET free (null) 6 -> 5
POUET free (null) 5 -> 4
POUET free (null) 4 -> 3
POUET free (null) 3 -> 2
POUET free (null) 2 -> 1
POUET free (null) 1 -> 0
POUET destroy (null)
POUET free (null) 1 -> 0
POUET destroy (null)
POUET free /usr/lib/pkcs11/pkcs11-spy.so 2 -> 1
[Thread 0xb0bffb90 (LWP 14686) exited]
[Thread 0xb51ffb90 (LWP 14670) exited]

Program exited normally.
(gdb)


I suspect the thread doing the C_WaitForSlotEvent() exits without calling PK11_FreeSlot().
I can see that the reference count is incremented (two times) just after the thread 14685 is created but the reference count is NOT decremented before thread 14685 exits (and after C_WaitForSlotEvent() exists by returning CKR_CRYPTOKI_NOT_INITIALIZED).
Comment 8 Nelson Bolyard (seldom reads bugmail) 2008-09-18 10:17:47 PDT
In reply to comment 6,
Most of the information shown in that comment is as expected and is believed
to be correct.  However, in the PKCS#11 interface trace for libgclib.so the 
call to C_FindObjectsInit with hSession = 0x0 is clearly bogus.  There were 
some changes made  in FF 3.0.2 to attempt to prevent that from happening.  
So I must ask: 
what version of FF was being used when the info in comment 6 was collected?

If it was not 3.0.2, I'd like to ask you to retry this test with FF 3.0.2.

One more request.  When you have large files of trace material, please attach
them to this bug as an attachment, rather than adding them as inline comments.
Thanks.
(I'll read comment 7 next)
Comment 9 Ludovic Rousseau 2008-09-18 11:31:40 PDT
I am using iceweasel from Debian unstable. Version number is 3.0.1-1. Version 3.0.2 is not yet available as a Debian package.

I didn't even noticed the error from C_FindObjectsInit(). I don't think this C_FindObjectsInit() problem is related with the missing C_Finalize() problem.

Sorry for the non-attached large files.
Comment 10 Nelson Bolyard (seldom reads bugmail) 2008-09-18 12:54:31 PDT
In the middle of the trace output for comment 7, we see this:

> 25: C_Finalize
> Returned:  400 CKR_CRYPTOKI_NOT_INITIALIZED
> Returned:  0 CKR_OK

Why did that function return that error code? 
I'd say that the previous 24 trace results above it are ample evidence 
that the module was, in fact, initialized.
Comment 11 Ludovic Rousseau 2008-09-18 13:47:14 PDT
25: C_Finalize
returned the 0 CKR_OK code

400 CKR_CRYPTOKI_NOT_INITIALIZED is returned by C_WaitForSlotEvent() (call 18).

The only way to stop a C_WaitForSlotEvent() is to call C_Finalize()

From PKCS#11 v2.20 page 104:
" Despite the fact that the parameters supplied to C_Initialize can in general allow for safe multi-threaded access to a Cryptoki library, the behavior of C_Finalize is nevertheless undefined if it is called by an application while other threads of the application are making Cryptoki calls.  The exception to this exceptional behavior of C_Finalize occurs when a thread calls C_Finalize while another of the application’s threads is blocking on Cryptoki’s C_WaitForSlotEvent function.  When this happens, the blocked thread becomes unblocked and returns the value CKR_CRYPTOKI_NOT_INITIALIZED.  See C_WaitForSlotEvent for more information. "
Comment 12 Nelson Bolyard (seldom reads bugmail) 2008-09-18 15:02:08 PDT
In reply to comment 11, thanks for the explanation.  I was wondering why
there appeared to be two return values.  I knew the effect that C_Finalize
has on C_WaitForSlotEvent, but didn't realize that the return value for 
another thread would show up there in the trace.
Comment 13 Ludovic Rousseau 2008-09-22 08:19:03 PDT
file ./security/nss/lib/pk11wrap/pk11util.c function SECMOD_WaitForAnyTokenEvent()

PK11SlotInfo *
SECMOD_WaitForAnyTokenEvent(SECMODModule *mod, unsigned long flags,
                         PRIntervalTime latency)
{
    CK_SLOT_ID id;
    CK_RV crv;
    PK11SlotInfo *slot;

    if (!pk11_getFinalizeModulesOption() ||
        ((mod->cryptokiVersion.major == 2) &&
         (mod->cryptokiVersion.minor < 1))) {
        /* if we are sharing the module with other software in our
         * address space, we can't reliably use C_WaitForSlotEvent(),
         * and if the module is version 2.0, C_WaitForSlotEvent() doesn't
         * exist */
    return secmod_HandleWaitForSlotEvent(mod, flags, latency);
    }
    /* first the the PKCS #11 call */
    PZ_Lock(mod->refLock);
    if (mod->evControlMask & SECMOD_END_WAIT) {
    goto end_wait;
    }
    mod->evControlMask |= SECMOD_WAIT_PKCS11_EVENT;
    PZ_Unlock(mod->refLock);
    crv = PK11_GETTAB(mod)->C_WaitForSlotEvent(flags, &id, NULL);
    PZ_Lock(mod->refLock);
    mod->evControlMask &= ~SECMOD_WAIT_PKCS11_EVENT;
    /* if we are in end wait, short circuit now, don't even risk
     * going into secmod_HandleWaitForSlotEvent */
    if (mod->evControlMask & SECMOD_END_WAIT) {
    goto end_wait;
    }
    PZ_Unlock(mod->refLock);
    if (crv == CKR_FUNCTION_NOT_SUPPORTED) {
    /* module doesn't support that call, simulate it */
    return secmod_HandleWaitForSlotEvent(mod, flags, latency);
    }
    if (crv != CKR_OK) {
    /* we can get this error if finalize was called while we were
     * still running. This is the only way to force a C_WaitForSlotEvent()
     * to return in PKCS #11. In this case, just return that there
     * was no event. */
    if (crv == CKR_CRYPTOKI_NOT_INITIALIZED) {
        PORT_SetError(SEC_ERROR_NO_EVENT);
    } else {
        PORT_SetError(PK11_MapError(crv));
    }
    return NULL;
    }
    slot = SECMOD_FindSlotByID(mod, id);
    if (slot == NULL) {
    /* possibly a new slot that was added? */
    SECMOD_UpdateSlotList(mod);
    slot = SECMOD_FindSlotByID(mod, id);
    }
    /* if we are in the delay period for the "isPresent" call, reset
     * the delay since we know things have probably changed... */
    if (slot && slot->nssToken && slot->nssToken->slot) {
    nssSlot_ResetDelay(slot->nssToken->slot);
    }
    return slot;

    /* must be called with the lock on. */
end_wait:
    mod->evControlMask &= ~SECMOD_END_WAIT;
    PZ_Unlock(mod->refLock);
    PORT_SetError(SEC_ERROR_NO_EVENT);
    return NULL;
}

So if/when C_WaitForSlotEvent() returns with CKR_CRYPTOKI_NOT_INITIALIZED when C_Finalize() is called the SECMOD_WaitForAnyTokenEvent() function will return with NULL.

SECMOD_WaitForAnyTokenEvent() is called from SmartCardMonitoringThread::Execute() in ./security/manager/ssl/src/nsSmartCardMonitor.cpp

//
// This is the main loop.
//
void SmartCardMonitoringThread::Execute()
{
  PK11SlotInfo *slot;
  const char *tokenName = nsnull;

  //
  // populate token names for already inserted tokens.
  //
  PK11SlotList *sl =
            PK11_FindSlotsByNames(mModule->dllName, nsnull, nsnull, PR_TRUE);
  PK11SlotListElement *sle;

  if (sl) {
    for (sle=PK11_GetFirstSafe(sl); sle;
                                      sle=PK11_GetNextSafe(sl,sle,PR_FALSE)) {
      SetTokenName(PK11_GetSlotID(sle->slot),
                  PK11_GetTokenName(sle->slot), PK11_GetSlotSeries(sle->slot));
    }
    PK11_FreeSlotList(sl);
  }

  // loop starts..
  do {
    slot = SECMOD_WaitForAnyTokenEvent(mModule, 0, PR_SecondsToInterval(1)  );
    if (slot == nsnull) {
      break;
    }

    // now we have a potential insertion or removal event, see if the slot
    // is present to determine which it is...
    if (PK11_IsPresent(slot)) {
      // insertion
      CK_SLOT_ID slotID = PK11_GetSlotID(slot);
      PRUint32 series = PK11_GetSlotSeries(slot);

      // skip spurious insertion events...
      if (series != GetTokenSeries(slotID)) {
        // if there's a token name, then we have not yet issued a remove
        // event for the previous token, do so now...
        tokenName = GetTokenName(slotID);
        if (tokenName) {
          SendEvent(NS_LITERAL_STRING(SMARTCARDEVENT_REMOVE), tokenName);
        }
        tokenName = PK11_GetTokenName(slot);
        // save the token name and series
        SetTokenName(slotID, tokenName, series);
        SendEvent(NS_LITERAL_STRING(SMARTCARDEVENT_INSERT), tokenName);
      }
    } else {
      // retrieve token name
      CK_SLOT_ID slotID = PK11_GetSlotID(slot);
      tokenName = GetTokenName(slotID);
      // if there's not a token name, then the software isn't expecting
      // a (or another) remove event.
      if (tokenName) {
        SendEvent(NS_LITERAL_STRING(SMARTCARDEVENT_REMOVE), tokenName);
        // clear the token name (after we send it)
        SetTokenName(slotID, nsnull, 0);
      }
    }
    PK11_FreeSlot(slot);

  } while (1);
}


The call to PK11_FreeSlot(slot) (at the end of the do/while loop) is made ONLY if/when SECMOD_WaitForAnyTokenEvent() returns with a non NULL slot pointer.

I can't find the PK11_ReferenceSlot() call associated with the PK11_FreeSlot(slot) present in the do/while loop.

I guess a PK11_FreeSlot(slot) is missing in the case of termination (when C_WaitForSlotEvent() returns CKR_CRYPTOKI_NOT_INITIALIZED). But I don't know (yet) where would be best place.
Comment 14 Nelson Bolyard (seldom reads bugmail) 2008-09-22 11:44:33 PDT
Ludovic,
It appears that you believe that a leaked slot reference is the cause of the
absence of a C_Finalize call to a particular PKCS#11 module, and you are 
looking for possible leaks.  That is indeed a likely explanation, IMO.  
I'm glad to see your interest and aptitude in pursuit of this.  
I will offer some explanation and make a request.  

First the request.  Instead of copying large amounts of source code into the
bug as inline comments, I suggest that you provide a URL that displays the 
relevant code.  Here are some example URLs for the code cited in comment 13.

http://mxr.mozilla.org/security/source/security/manager/ssl/src/nsSmartCardMonitor.cpp#303

http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/security/manager/ssl/src/nsSmartCardMonitor.cpp&rev=1.3&mark=305,342#303

Now the explanation.  The PK11_ReferenceSlot() call that you seek takes place
in code called by SECMOD_WaitForAnyTokenEvent.  
SECMOD_WaitForAnyTokenEvent calls SECMOD_FindSlotByID at 
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/security/nss/lib/pk11wrap/pk11util.c&rev=1.53&mark=1105,1109#1105

SECMOD_FindSlotByID calls PK11_ReferenceSlot at
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/security/nss/lib/pk11wrap/pk11util.c&rev=1.53&mark=290#279

It is customary in NSS for functions that find and return slots to have 
already bumped the reference count on the slot before returning it.  
We say that those functions "return a new reference" to the slot.  
Perhaps Not all functions that return slot pointers do that, but most do.
Comment 15 Nelson Bolyard (seldom reads bugmail) 2008-09-22 11:52:29 PDT
I have reported two probable slot leaks in Bug 456409.  They may or may not 
be the cause of this bug.
Comment 16 Ludovic Rousseau 2008-09-23 08:15:19 PDT
I think I found the bug :-)

Function PK11_FindSlotsByNames() in security/nss/lib/pk11wrap/pk11slot.c is doing
http://mxr.mozilla.org/security/source/security/nss/lib/pk11wrap/pk11slot.c#557

557                     PK11SlotInfo* slot = PK11_ReferenceSlot(tmpSlot);
558                     if (slot) {
559                         PK11_AddSlotToList(slotList, slot);
560                         slotcount++;
561                     }

PK11_ReferenceSlot() (line 557) will increase the refCount by copying the tmpSlot reference

PK11_AddSlotToList() (line 559) will internally call PK11_ReferenceSlot() (http://mxr.mozilla.org/security/source/security/nss/lib/pk11wrap/pk11slot.c#211) and then refCount will be increased again.

The slot pointer content is lost but a PK11_FreeSlot() is missing

Proposed patch:
--- ./security/nss/lib/pk11wrap/pk11slot.c      2008-09-18 15:12:19.000000000 +0200
+++ ./security/nss/lib/pk11wrap/pk11slot.c   2008-09-23 16:01:06.000000000 +0200
@@ -561,6 +561,7 @@
                     if (slot) {
                         PK11_AddSlotToList(slotList, slot);
                         slotcount++;
+                         PK11_FreeSlot(slot);
                     }
                 }
             }


I tested the patch and it correct the bug I have. Please confirm this patch is correct and apply it.
Comment 17 Nelson Bolyard (seldom reads bugmail) 2008-09-23 09:38:09 PDT
Ludovic,

Please provide the call stack for a call to PK11_FindSlotsByNames that you
believe leaks a slot.  Thanks.
Comment 18 Nelson Bolyard (seldom reads bugmail) 2008-09-23 09:40:21 PDT
Let us suppose that this function PK11_FindSlotsByNames, or any NSS function,
habitually leaks slots.  Then why would it do so only after a call to 
SECMOD_CancelWait?
Comment 19 Ludovic Rousseau 2008-09-23 11:47:25 PDT
The slot leak happens _before_ SECMOD_CancelWait.

PK11_FindSlotsByNames() is called in SmartCardMonitoringThread::Execute()
http://mxr.mozilla.org/security/source/security/manager/ssl/src/nsSmartCardMonitor.cpp#291
before the call to SECMOD_WaitForAnyTokenEvent() so a long before the call to SECMOD_CancelWait().

You can see that in my Comment #7.
[...]
[New Thread 0xb1591b90 (LWP 14685)]
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 1 -> 2
POUET reference /usr/lib/pkcs11/pkcs11-spy.so 2 -> 3
POUET free /usr/lib/pkcs11/pkcs11-spy.so 3 -> 2


18: C_WaitForSlotEvent
[...]

The refCount does +1 +1 -1. One -1 is missing. The leak is here.

If you still need a backtrace I will provide it on thursday (in 2 days).
Comment 20 Ludovic Rousseau 2008-09-25 01:37:19 PDT
Backtrace of PK11_FindSlotsByNames call:

Breakpoint 1, PK11_FindSlotsByNames (
    dllName=0xb362a090 "/usr/lib/pkcs11/pkcs11-spy.so", slotName=0x0,
    tokenName=0x0, presentOnly=1) at pk11slot.c:517
517         SECMODModuleList *modules = SECMOD_GetDefaultModuleList();
Current language:  auto; currently c
(gdb) bt
#0  PK11_FindSlotsByNames (dllName=0xb362a090 "/usr/lib/pkcs11/pkcs11-spy.so",
    slotName=0x0, tokenName=0x0, presentOnly=1) at pk11slot.c:517
#1  0xb767fcf2 in SmartCardMonitoringThread::Execute (this=0xb3629720)
    at nsSmartCardMonitor.cpp:291
#2  0xb7c5c7d1 in ?? () from /usr/lib/libnspr4.so.0d
#3  0xb3629720 in ?? ()
#4  0xb37d6e20 in ?? ()
#5  0x00000000 in ?? ()
(gdb)

I had no other calls to PK11_FindSlotsByNames() during the execution.


I also backtraced the PK11_ReferenceSlot() and PK11_FreeSlot() calls.

PK11_ReferenceSlot() is called at http://mxr.mozilla.org/security/source/security/nss/lib/pk11wrap/pk11slot.c#557

Breakpoint 3, PK11_ReferenceSlot (slot=0xb3681000) at pk11slot.c:418
418             printf("POUET reference %s %d -> %d\n", slot->module->dllName, slot->refCount, slot->refCount+1);
(gdb) p slot->module->dllName
$3 = 0xb3628090 "/usr/lib/pkcs11/pkcs11-spy.so"
(gdb) bt
#0  PK11_ReferenceSlot (slot=0xb3681000) at pk11slot.c:418
#1  0xb6de9e21 in PK11_FindSlotsByNames (
    dllName=0xb3628090 "/usr/lib/pkcs11/pkcs11-spy.so", slotName=0x0,
    tokenName=0x0, presentOnly=1) at pk11slot.c:560
#2  0xb7713cf2 in SmartCardMonitoringThread::Execute (this=0xb3627720)
    at nsSmartCardMonitor.cpp:291
#3  0xb7c2d7d1 in ?? () from /usr/lib/libnspr4.so.0d
#4  0xb3627720 in ?? ()
#5  0xb37d6e20 in ?? ()
#6  0x00000000 in ?? ()


PK11_ReferenceSlot() is called at http://mxr.mozilla.org/security/source/security/nss/lib/pk11wrap/pk11slot.c#211

Breakpoint 3, PK11_ReferenceSlot (slot=0xb3681000) at pk11slot.c:418
418             printf("POUET reference %s %d -> %d\n", slot->module->dllName, slot->refCount, slot->refCount+1);
(gdb) p slot->module->dllName
$4 = 0xb3628090 "/usr/lib/pkcs11/pkcs11-spy.so"
(gdb) bt
#0  PK11_ReferenceSlot (slot=0xb3681000) at pk11slot.c:418
#1  0xb6de959c in PK11_AddSlotToList (list=0xb36277a0, slot=0xb3681000)
    at pk11slot.c:211
#2  0xb6de9e35 in PK11_FindSlotsByNames (
    dllName=0xb3628090 "/usr/lib/pkcs11/pkcs11-spy.so", slotName=0x0,
    tokenName=0x0, presentOnly=1) at pk11slot.c:562
#3  0xb7713cf2 in SmartCardMonitoringThread::Execute (this=0xb3627720)
    at nsSmartCardMonitor.cpp:291
#4  0xb7c2d7d1 in ?? () from /usr/lib/libnspr4.so.0d
#5  0xb3627720 in ?? ()
#6  0xb37d6e20 in ?? ()
#7  0x00000000 in ?? ()


PK11_FreeSlot() is called at http://mxr.mozilla.org/security/source/security/manager/ssl/src/nsSmartCardMonitor.cpp#300

Breakpoint 2, PK11_FreeSlot (slot=0xb3681000) at pk11slot.c:461
461             printf("POUET free %s %d -> %d\n", slot->module->dllName, slot->refCount, slot->refCount-1);
(gdb) bt
#0  PK11_FreeSlot (slot=0xb3681000) at pk11slot.c:461
#1  0xb6de8554 in PK11_FreeSlotListElement (list=0xb36277a0, le=0xb3627d20)
    at pk11slot.c:166
#2  0xb6de8593 in pk11_FreeSlotListStatic (list=0xb36277a0) at pk11slot.c:180
#3  0xb6de86c4 in PK11_FreeSlotList (list=0xb36277a0) at pk11slot.c:196
#4  0xb7713d67 in SmartCardMonitoringThread::Execute (this=0xb3627720)
    at nsSmartCardMonitor.cpp:300
#5  0xb7c2d7d1 in ?? () from /usr/lib/libnspr4.so.0d
#6  0xb3627720 in ?? ()
#7  0xb37d6e20 in ?? ()
#8  0x00000000 in ?? ()


In manager/ssl/src/nsSmartCardMonitor.cpp, the slot list sl created line 290 is then freed line 300. But a PK11_FreeSlot() is missing.
Comment 21 Nelson Bolyard (seldom reads bugmail) 2008-09-25 09:45:13 PDT
The stack traces in the preceding comment claim that function 
PK11_FindSlotsByNames resides in "/usr/lib/pkcs11/pkcs11-spy.so".
Is this so?  Or is your debugger merely mistaken about that?

If you have third party shared libraries that are replacing functions in
NSS shared libraries, all bets are off.  

BTW, the doesn't appear to be anything wrong with the loop that manipulates
the slot list in nsSmartCardMonitor.cpp near line 290.  It does not appear
to leak any slots.
Comment 22 Ludovic Rousseau 2008-09-25 12:08:20 PDT
No, PK11_FindSlotsByNames is in pk11slot.c.

"/usr/lib/pkcs11/pkcs11-spy.so" is the value of dllName variable.
Comment 23 Ludovic Rousseau 2008-09-25 12:12:34 PDT
(In reply to comment #21)
> BTW, the doesn't appear to be anything wrong with the loop that manipulates
> the slot list in nsSmartCardMonitor.cpp near line 290.  It does not appear
> to leak any slots.

Sure. The problem is NOT in SmartCardMonitoringThread::Execute() in nsSmartCardMonitor.cpp near line 290. This function is correct.

The problem is in PK11_FindSlotsByNames(). I proposed a patch in comment 16.
Comment 24 Julien Pierre 2008-09-25 16:29:59 PDT
Ludovic, you are right. The problem is in code that I wrote, so I'm taking this bug.
Comment 25 Julien Pierre 2008-09-25 16:34:57 PDT
Created attachment 340461 [details] [diff] [review]
Plug slot reference leak

This cleans up the code and is OK since PK11_AddSlotToList creates its own slot reference.
Comment 26 Nelson Bolyard (seldom reads bugmail) 2008-09-25 16:51:47 PDT
Comment on attachment 340461 [details] [diff] [review]
Plug slot reference leak

r=nelson
Comment 27 Julien Pierre 2008-09-25 17:02:33 PDT
Thanks for the review, Nelson. I checked in the fix to the trunk.

Checking in pk11slot.c;
/cvsroot/mozilla/security/nss/lib/pk11wrap/pk11slot.c,v  <--  pk11slot.c
new revision: 1.95; previous revision: 1.94
done

Note You need to log in before you can comment on or make changes to this bug.