Closed Bug 400238 Opened 17 years ago Closed 17 years ago

softtoken unexpectedly logged out

Categories

(NSS :: Libraries, defect, P3)

Product:
NSS
Component:
Libraries
Platform:
x86
macOS
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: Dolske, Assigned: rrelyea)

References

Details

Attachments

(7 files, 1 obsolete file)

key3.db
16.00 KB, application/octet-stream
Details
pkcs11.log
140.39 KB, text/plain
Details
Dummy HTML file
139 bytes, text/plain
Details
Annotated log.
143.85 KB, text/x-log
Details
smaller test case
6.09 KB, patch
Details | Diff | Splinter Review
Test patch
7.02 KB, patch
Details | Diff | Splinter Review
Test case cleanup
8.21 KB, patch
nelson
: review+
Details | Diff | Splinter Review
Over in bug 397719, Ryan found that his testcase was getting an error from password manager when adding a test login. The specific exception being caught is normally an indication that the user didn't enter their master password, and so password was unable to save an encrypted value. This is unexpected, because the browser chrome test being run creates a new profile, and does not set a master password. This should be no different than creating a new Firefox profile, but I can't reproduce the problem that way. Only the test exhibits the problem. Something's clearly different in the two scenarios, but I can't figure out what it is. From the password manager's perspective, the failure happens in _encrypt() in storage-Legacy.js, when it asks the SDR (nsISecretDecoderRing) to encrypt the username of the login being added: 852 cipherText = this._decoderRing.encryptString(plainOctet); XPCOM throws an exception, because SDR returned NS_ERROR_FAILURE. I did some debugging with gdb, and found that the error happens very late in the process... It can't find the 3DES key in key3.db, so it creates one, and then fails in sftk_ExtractTemplate when preparing to add it to the DB. One of the key attributes is private, so it's attempting to encrypt it, but the expected passwordKey is missing. This is the code it's hitting: 647 if (handle->passwordKey.data == NULL) { 648 PZ_Unlock(handle->passwordLock); 649 *crv = CKR_USER_NOT_LOGGED_IN; 650 break; 651 } This seems strange, because we passed through sftk_handleObject a few frames back, and the "are we logged in?" checks did not trigger an error: 1368 /* don't create a private object if we aren't logged in */ 1369 if ((!slot->isLoggedIn) && (slot->needLogin) && 1370 (sftk_isTrue(object,CKA_PRIVATE))) { 1371 return CKR_USER_NOT_LOGGED_IN; 1372 } Seems like something is probably out of sync here. I'll attach some gdb info in the next comment. My laptop keeps hanging when running gdb, and this will be my 3rd attempt at submitting this bug. :-)
(gdb) break sftk_ExtractTemplate Breakpoint 1 at 0x28027b02: file sftkdb.c, line 583. (gdb) break sftkdb.c:644 Breakpoint 2 at 0x28027d07: file sftkdb.c, line 644. Run the tests... 647 if (handle->passwordKey.data == NULL) { (gdb) n 648 PZ_Unlock(handle->passwordLock); (gdb) bt #0 sftk_ExtractTemplate (arena=0x20189b90, object=0x1a12000, handle=0x23be8c80, pcount=0xbfffa9c0, crv=0xbfffa9bc) at sftkdb.c:648 #1 0x28027edc in sftkdb_write (handle=0x23be8c80, object=0x1a12000, objectID=0x1a1200c) at sftkdb.c:701 #2 0x2800d7a8 in sftk_handleSecretKeyObject (session=0x203398b0, object=0x1a12000, key_type=21, isFIPS=0) at pkcs11.c:1174 #3 0x2800d9d7 in sftk_handleKeyObject (session=0x203398b0, object=0x1a12000) at pkcs11.c:1228 #4 0x2800e010 in sftk_handleObject (object=0x1a12000, session=0x203398b0) at pkcs11.c:1443 #5 0x2801921f in NSC_GenerateKey (hSession=16777227, pMechanism=0xbfffac68, pTemplate=0xbfffac74, ulCount=5, phKey=0x237b3b74) at pkcs11c.c:3111 #6 0x26044350 in PK11_TokenKeyGenWithFlags (slot=0x1c6f600, type=307, param=0x0, keySize=0, keyid=0x262e35e0, opFlags=2304, attrFlags=5, wincx=0x2030c930) at pk11skey.c:986 #7 0x26044461 in PK11_TokenKeyGen (slot=0x1c6f600, type=307, param=0x0, keySize=0, keyid=0x262e35e0, isToken=1, wincx=0x2030c930) at pk11skey.c:1034 #8 0x260444fe in PK11_GenDES3TokenKey (slot=0x1c6f600, keyid=0x262e35e0, cx=0x2030c930) at pk11skey.c:1054 #9 0x260421e9 in PK11SDR_Encrypt (keyid=0xbfffaeb0, data=0xbfffaea4, result=0xbfffae98, cx=0x2030c930) at pk11sdr.c:208 #10 0x16bcb2e7 in nsSecretDecoderRing::Encrypt (this=0x2035d670, data=0x20337a20 "dolske", dataLen=6, result=0xbfffaf04, _retval=0xbfffaf00) at /Users/dolske/ff/ff-trunk/mozilla/security/manager/ssl/src/nsSDR.cpp:167 ... (gdb) p *tp $3 = { type = 17, pValue = 0x1a122ac, ulValueLen = 24 }
Attached file key3.db —
This is the key3.db that exists when we're in the midst of encrypting the username (I assume it should be in a consistent state, since things seem to fail before actually storing anything.) I think the key question here (ha-ha) is (1) when is "passwordKey" normally expected to be generated, and (2) what could cause the this environment to trigger it differently than a normal browser run?
Sorry for the commentspam, but I thought I should describe how to reproduce the problem with the tests: 1) Apply the "Patch v2 + tests" attachment from bug 397719 to /browser 2) Build 3) From your object dir, run "perl _tests/testing/mochitest/runtests.pl --browser-chrome" 4) Click the "Run All Tests" button. 5) Stuff will start running, ~40 seconds later the summary appears in the window. About a page from the bottom, you'll see: ... PASS - History test setup successfully PASS - Form history test setup successfully PASS - Download test setup successfully FAIL - Exception thrown - [Exception... "'Couldn't write to file, login not added.' when calling method: [nsILoginManagerStorage::addLogin]" nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)" location: "JS frame :: file:///Users/dolske/ff/ff-trunk/mozilla/obj-ff/dist/MinefieldDebug.app/Contents/MacOS/components/nsLoginManager.js :: anonymous :: line 364" data: no] - chrome://mochikit/content/browser/browser/modules/browser_sanitizer.js chrome://mochikit/content/browser/docshell/test/browser/browser_bug349769.js PASS - Forced principal must not be null when loading undefined PASS - Forced principal must not be undefined when loading undefined PASS - Forced principal must not be system when loading undefined ...
This sounds faintly like another bug. What is the size of the key3.db file with which the problem is seen? 16 KB? 12 KB?
Assignee: nobody → rrelyea
It does sound similar to bug 393835 (which is what I assume you're thinking of), although in this case the key3.db is 16K and Firefox using the NSS tag with that fix.
Bug 403092 is from an end user who ran into this problem (after deleting their profile to start with a clean slate), so obviously this isn't just some quirk only exposed in the test harness.
Flags: blocking1.9?
Please give the steps to reproduce this problem.
Clarifying my request: Please give steps that an ordinary end user can do with his new FireFox installation to reproduce this. (I know you said in comment 0 that you haven't figured out how to do that yet.) It seems to me that the issue here is that softoken returns CKR_USER_NOT_LOGGED_IN in response to some operation (NSC_GenerateKey) after some number of previous operations (unspecified here) have been performed, which have set the expectation that there should be on login issue at this point. It might help if we knew the full details of those preceding operations. A PKCS#11 interface trace would be really informative. (This is a feature of NSS in DEBUG builds when certain environment variables are set.) I suspect that the preceding operations don't require a login, and so they succeeded in the absence of a login. Then this operation fails because ... Hmm, here's a thought. Is it possible that the test has gotten the softoken into FIPS mode? Does FF's UI for managing PKCS#11 modules show whether the module is in FIPS mode or not? I don't recall if it does. In FIPS mode, softoken requires that the user be logged in for certain operations that do not require login in non-FIPS mode. We can't tell that from the supplied key DB. We would also need the cert DB and the secmod.db files that existed when it was in this state.
Having studied the new code some more, it's apparent that the token really is logged out, and that some previous operation logged it out, perhaps as an unintended side effect. I'd really like to see that PKCS#11 interface trace.
BTW, note that unless we find that some operation caused the token to become logged out when it should not have done that, then the alternative is that the token became logged out because some code outside of softoken told it to do so. In that case, this is NOT an NSS bug. Until we can get a trace of events, we can only speculate.
Summary: uninitialized passwordKey in softtoken? → softtoken unexpectedly logged out
As aside effect of the merge database patch, I've removed the internal 'isLoggedIn' variable and made that state completely dependent on the state of handle->passwordKey.data. bob
(In reply to comment #9) > It might help if we knew the full details of those preceding operations. > A PKCS#11 interface trace would be really informative. (This is a feature > of NSS in DEBUG builds when certain environment variables are set.) Do you have a link to something describing how to enable that? I'm also going to try reproducing this on Solaris, if I can I'll provide a truss log of the NSS calls being made. > Hmm, here's a thought. Is it possible that the test has gotten the softoken > into FIPS mode? Does FF's UI for managing PKCS#11 modules show whether the > module is in FIPS mode or not? I don't recall if it does. Seems unlikely, as I'm not sure what in the test environment would have any interest in enabling FIPS.
Dolske can you set a priority on this?
Flags: blocking1.9? → blocking1.9+
Priority: -- → P3
Does this trigger a log out? 00 xul!nsSecretDecoderRing::LogoutAndTeardown(void) [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\security\manager\ssl\src\nssdr.cpp @ 347] 01 xul!NS_InvokeByIndex_P(class nsISupports * that = 0x03287c40, unsigned int methodIndex = 9, unsigned int paramCount = 0, struct nsXPTCVariant * params = 0x0012d520)+0x27 [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\xpcom\reflect\xptcall\src\md\win32\xptcinvoke.cpp @ 102] 02 xul!XPCWrappedNative::CallMethod(class XPCCallContext * ccx = 0x03287c40, XPCWrappedNative::CallMode mode = 52984896 (No matching enumerant))+0x532 [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\js\src\xpconnect\src\xpcwrappednative.cpp @ 2371] 03 xul!XPC_WN_OnlyIWrite_PropertyStub(struct JSContext * cx = 0x5618246c, struct JSObject * obj = 0x1424748b, long idval = 209423191, long * vp = 0x0ffce783)+0x3b [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\js\src\xpconnect\src\xpcwrappednativejsops.cpp @ 500] 04 xul!XPC_WN_OnlyIWrite_PropertyStub(struct JSContext * cx = 0x60144dd0, struct JSObject * obj = 0x00000000, long idval = 19202057, long * vp = 0x00000000)+0xed [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\js\src\xpconnect\src\xpcwrappednativejsops.cpp @ 508] 05 js3250!js_DefineNativeProperty(struct JSContext * cx = 0x00000000, struct JSObject * obj = 0x0121062c, long id = 18941484, long value = 0, <function> * getter = 0x00000000, <function> * setter = 0x00177288, unsigned int attrs = 0xffffffff, unsigned int flags = 0, int shortid = 0, struct JSProperty ** propp = 0x00000000)+0x401 [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\js\src\jsobj.c @ 3111] 06 MOZCRT19!arena_malloc_small(struct arena_s * arena = 0x00090009, unsigned int size = 0x3287c40, int zero = 1616272672)+0x144 [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\obj-fx-trunk\memory\jemalloc\src\jemalloc.c @ 3659] 07 xul!DefinePropertyIfFound(class XPCCallContext * ccx = <Memory access error>, struct JSObject * obj = <Memory access error>, long idval = <Memory access error>, class XPCNativeSet * set = 0x00000009, class XPCNativeInterface * iface = <Memory access error>, class XPCNativeMember * member = <Memory access error>, class XPCWrappedNativeScope * scope = <Memory access error>, int reflectToStringAndToSource = <Memory access error>, class XPCWrappedNative * wrapperToReflectInterfaceNames = <Memory access error>, class XPCWrappedNative * wrapperToReflectDoubleWrap = <Memory access error>, class XPCNativeScriptableInfo * scriptableInfo = <Memory access error>, unsigned int propFlags = <Memory access error>, int * resolved = <Memory access error>)+0x2bb [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\js\src\xpconnect\src\xpcwrappednativejsops.cpp @ 488] 08 js3250!js_Invoke(struct JSContext * cx = <Memory access error>, unsigned int argc = <Memory access error>, long * vp = <Memory access error>, unsigned int flags = <Memory access error>)+0x2c9 [e:\builds\tinderbox\fx-trunk\winnt_5.2_depend\mozilla\js\src\jsinterp.c @ 1275] I've been using clear private data to get rid of http auth sessions, and i noticed that i couldn't store passwords after doing so. Unfortunately it doesn't seem to be quite sufficient to reproduce this problem.
(In reply to comment #13) > > A PKCS#11 interface trace would be really informative. (This is a feature > > of NSS in DEBUG builds when certain environment variables are set.) > > Do you have a link to something describing how to enable that? http://www.mozilla.org/projects/security/pki/nss/tech-notes/tn2.html
Attached file pkcs11.log —
This is a pkcs11 log (made with steps from previous comment, on a current FF3 trunk debug build). I followed the basic steps in bug 426543 comment 3 (using a local HTML page instead of Gmail, to avoid any noise from doing SSL). 1. Create a new profile. 2. Load dummy HTML form, enter a login, submit. 3. On the notification bar, click "Remember" button to save login. 4. Clear Private Data (using the default items that are checked). 5. On dummy HTML page, enter a different login, submit 6. Click the remember button I suspect this might be something only triggered when logging out from the token during the same browser session which initialized it. If I launch the browser and immediately quit (between steps 1 and 2), I can't reproduce the problem the next time I run the browser.
Attached file Dummy HTML file —
Save locally, use in testcase described in previous comment.
Attachment #313279 - Attachment mime type: application/octet-stream → text/plain
I looked through the log file, looking for anomalous results of PKCS#11 operations (basically operations that returned a non-zero result value). Most of them were the intentional stuff (doing a C_*final just before a C_*Init to make sure the context is cleared out), but I did find 3 items that looked odd. Bob Relyea can probably tell at a glance what's up here. 1. Double C_EncryptFinal call on a triple-DES block of only 8 bytes. :-o Q: What do we ever 3DES encrypt that is only 8 bytes long? (The answer is probably in SDR) 2961 -1604624480[609cd0]: C_OpenSession 2962 -1604624480[609cd0]: slotID = 0x2 2963 -1604624480[609cd0]: flags = 0x4 2964 -1604624480[609cd0]: pApplication = 0xc3ae00 2965 -1604624480[609cd0]: Notify = 0x14256887 2966 -1604624480[609cd0]: phSession = 0xbfff9d9c 2967 -1604624480[609cd0]: *phSession = 0x1000006 2968 -1604624480[609cd0]: rv = 0x0 2969 -1604624480[609cd0]: C_EncryptInit 2970 -1604624480[609cd0]: hSession = 0x1000006 2971 -1604624480[609cd0]: pMechanism = 0xbfff9ddc 2972 -1604624480[609cd0]: hKey = 0xd8000000 2973 -1604624480[609cd0]: mechanism = 0x133 2974 -1604624480[609cd0]: rv = 0x0 2975 -1604624480[609cd0]: C_EncryptUpdate 2976 -1604624480[609cd0]: hSession = 0x1000006 2977 -1604624480[609cd0]: pPart = 0x1d7e57e0 2978 -1604624480[609cd0]: ulPartLen = 8 2979 -1604624480[609cd0]: pEncryptedPart = 0x1f6ab810 2980 -1604624480[609cd0]: pulEncryptedPartLen = 0xbfff9e08 2981 -1604624480[609cd0]: *pulEncryptedPartLen = 0x8 2982 -1604624480[609cd0]: rv = 0x0 2983 -1604624480[609cd0]: C_EncryptFinal 2984 -1604624480[609cd0]: hSession = 0x1000006 2985 -1604624480[609cd0]: pLastEncryptedPart = 0x0 2986 -1604624480[609cd0]: pulLastEncryptedPartLen = 0xbfff9df4 2987 -1604624480[609cd0]: *pulLastEncryptedPartLen = 0x0 2988 -1604624480[609cd0]: rv = 0x0 2989 -1604624480[609cd0]: C_EncryptFinal 2990 -1604624480[609cd0]: hSession = 0x1000006 2991 -1604624480[609cd0]: pLastEncryptedPart = 0xbfff9cf4 2992 -1604624480[609cd0]: pulLastEncryptedPartLen = 0xbfff9df4 2993 -1604624480[609cd0]: *pulLastEncryptedPartLen = 0x0 2994 * -1604624480[609cd0]: rv = 0x91 2995 -1604624480[609cd0]: C_CloseSession 2996 -1604624480[609cd0]: hSession = 0x1000006 2997 -1604624480[609cd0]: rv = 0x0 At the end of the encryption, we asked it "how many bytes are you going to give me in the last output block?" (lines 2983-2986) and it answered "none" (lines 1987-2988). Then we went ahead and said "OK, give me that last final block", and it said "there's no operation in progress". I think that's a bug. But I'm not exactly sure what the bug was. Given that this is not a padded mechanism, the last block will always be zero length, so maybe we should not be asking it for the length of the last block. Or maybe it shouldn't be finalizing the session, given that we were just asking "how much" and not actually asking for the output. (I think that's it.) It's possible that, even though we got all the encrypted output, we decided there was an error and didn't proceed as if it had succeeded. 2. Almost immediately after that error above, (just two C_SeedRandom calls later), we see this 3008 -1604624480[609cd0]: WARNING: dependent window created without a parent: file /Users/dolske/ff/trunk1/mozilla/toolkit/components/startup/src/nsAppStartup.cpp, line 458 3009 -1604624480[609cd0]: WARNING: failed to recent frecency: file /Users/dolske/ff/trunk1/mozilla/toolkit/components/places/src/nsNavHistoryExpire.cpp, line 262 3010 -1604624480[609cd0]: C_Logout 3011 -1604624480[609cd0]: hSession = 0x1 3012 * -1604624480[609cd0]: rv = 0x101 There's an attempt to Logout of a session, with a response of "user not logged in", followed immediately by a successful logout (below). 3013 -1604624480[609cd0]: C_Logout 3014 -1604624480[609cd0]: hSession = 0x1000001 3015 -1604624480[609cd0]: rv = 0x0 3016 -1604624480[609cd0]: WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /Users/dolske/ff/trunk1/mozilla/xpcom/io/nsLocalFileOSX.mm, line 482 Justin, Is that last error above the one you noticed? SO, I think we got an unexpected result from the encryption attempt, and then things went downhill quickly at that point. We need to study some error-handling execution paths OBTW, (like 3009) in what language is "frecency" a word? And how does one recent a frecency? :) 3. Finally, quite a while later, after lots and lots of C_FindObjects operations on session 0x1000001, we see: 3288 -1604624480[609cd0]: C_OpenSession 3289 -1604624480[609cd0]: slotID = 0x2 3290 -1604624480[609cd0]: flags = 0x6 3291 -1604624480[609cd0]: pApplication = 0xc3ae00 3292 -1604624480[609cd0]: Notify = 0x14256887 3293 -1604624480[609cd0]: phSession = 0xbfff9c64 3294 -1604624480[609cd0]: *phSession = 0x1000007 3295 -1604624480[609cd0]: rv = 0x0 3296 -1604624480[609cd0]: C_GenerateKey 3297 -1604624480[609cd0]: hSession = 0x1000007 3298 -1604624480[609cd0]: pMechanism = 0xbfff9cb8 3299 -1604624480[609cd0]: pTemplate = 0xbfff9cc4 3300 -1604624480[609cd0]: ulCount = 5 3301 -1604624480[609cd0]: phKey = 0x1f87ec64 3302 -1604624480[609cd0]: CKA_ID = 0x144186d0 [16] 3303 -1604624480[609cd0]: CKA_TOKEN = CK_TRUE [1] 3304 -1604624480[609cd0]: CKA_PRIVATE = CK_TRUE [1] 3305 -1604624480[609cd0]: CKA_ENCRYPT = CK_TRUE [1] 3306 -1604624480[609cd0]: CKA_SIGN = CK_TRUE [1] 3307 -1604624480[609cd0]: mechanism = 0x131 3308 -1604624480[609cd0]: *phKey = 0x0 3309 * -1604624480[609cd0]: rv = 0x101 3310 -1604624480[609cd0]: C_CloseSession 3311 -1604624480[609cd0]: hSession = 0x1000007 3312 -1604624480[609cd0]: rv = 0x0 That's an attempt to generate a triple-DES key (?!) which fails because CKR_USER_NOT_LOGGED_IN. This appears to be an aftermath of the previous failure.
I don't think the following is the problem.... 2961 -1604624480[609cd0]: C_OpenSession 2962 -1604624480[609cd0]: slotID = 0x2 2963 -1604624480[609cd0]: flags = 0x4 2964 -1604624480[609cd0]: pApplication = 0xc3ae00 2965 -1604624480[609cd0]: Notify = 0x14256887 2966 -1604624480[609cd0]: phSession = 0xbfff9d9c 2967 -1604624480[609cd0]: *phSession = 0x1000006 2968 -1604624480[609cd0]: rv = 0x0 2969 -1604624480[609cd0]: C_EncryptInit 2970 -1604624480[609cd0]: hSession = 0x1000006 2971 -1604624480[609cd0]: pMechanism = 0xbfff9ddc 2972 -1604624480[609cd0]: hKey = 0xd8000000 2973 -1604624480[609cd0]: mechanism = 0x133 2974 -1604624480[609cd0]: rv = 0x0 2975 -1604624480[609cd0]: C_EncryptUpdate 2976 -1604624480[609cd0]: hSession = 0x1000006 2977 -1604624480[609cd0]: pPart = 0x1d7e57e0 2978 -1604624480[609cd0]: ulPartLen = 8 2979 -1604624480[609cd0]: pEncryptedPart = 0x1f6ab810 2980 -1604624480[609cd0]: pulEncryptedPartLen = 0xbfff9e08 2981 -1604624480[609cd0]: *pulEncryptedPartLen = 0x8 2982 -1604624480[609cd0]: rv = 0x0 2983 -1604624480[609cd0]: C_EncryptFinal 2984 -1604624480[609cd0]: hSession = 0x1000006 2985 -1604624480[609cd0]: pLastEncryptedPart = 0x0 2986 -1604624480[609cd0]: pulLastEncryptedPartLen = 0xbfff9df4 2987 -1604624480[609cd0]: *pulLastEncryptedPartLen = 0x0 2988 -1604624480[609cd0]: rv = 0x0 2989 -1604624480[609cd0]: C_EncryptFinal 2990 -1604624480[609cd0]: hSession = 0x1000006 2991 -1604624480[609cd0]: pLastEncryptedPart = 0xbfff9cf4 2992 -1604624480[609cd0]: pulLastEncryptedPartLen = 0xbfff9df4 2993 -1604624480[609cd0]: *pulLastEncryptedPartLen = 0x0 2994 * -1604624480[609cd0]: rv = 0x91 2995 -1604624480[609cd0]: C_CloseSession 2996 -1604624480[609cd0]: hSession = 0x1000006 2997 -1604624480[609cd0]: rv = 0x0 The reason is the code that generates this at the pk11wrap level is: ctx = PK11_CreateContextBySymKey(type, CKA_ENCRYPT, key, params); if (!ctx) { rv = SECFailure; goto loser; } rv = padBlock(data, PK11_GetBlockSize(type, 0), &paddedData); if (rv != SECSuccess) goto loser; sdrResult.data.len = paddedData.len; sdrResult.data.data = (unsigned char *)PORT_ArenaAlloc(arena, sdrResult.data.len); rv = PK11_CipherOp(ctx, sdrResult.data.data, (int*)&sdrResult.data.len, sdrResult.data.len, paddedData.data, paddedData.len); if (rv != SECSuccess) goto loser; PK11_Finalize(ctx); The finalize call in this case is not expecting any data, and is ignoring any errors back from finalize (basically either we succeed to finalize and the session is final or we didn't, in which case it won't matter in a few milliseconds when we close the session). That doesn't seem to be the problem..
> 2. Almost immediately after that error above, (just two C_SeedRandom calls > later), we see this This probably isn't immediate. C_SeedRandom calls happen typically as part of user or network interaction. > 3008 -1604624480[609cd0]: WARNING: dependent window created without a parent: > file > /Users/dolske/ff/trunk1/mozilla/toolkit/components/startup/src/nsAppStartup.cpp, > line 458 > 3009 -1604624480[609cd0]: WARNING: failed to recent frecency: file > /Users/dolske/ff/trunk1/mozilla/toolkit/components/places/src/nsNavHistoryExpire.cpp, > line 262 > 3010 -1604624480[609cd0]: C_Logout > 3011 -1604624480[609cd0]: hSession = 0x1 > 3012 * -1604624480[609cd0]: rv = 0x101 > 3013 -1604624480[609cd0]: C_Logout > 3014 -1604624480[609cd0]: hSession = 0x1000001 > 3015 -1604624480[609cd0]: rv = 0x0 > 3016 -1604624480[609cd0]: WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with > result 0x80520012: file > /Users/dolske/ff/trunk1/mozilla/xpcom/io/nsLocalFileOSX.mm, line 482 My guess is this is the result of the 'Clear Private Data (using the default items that are checked)' call.... I suspect it calls logout. It's clear someone is trying to log out of all the tokens. That's why there is to logouts here, each against 'primordial' sessions (one against the crypto slot, which is never logged in, the other against the internal slot (which is). I'm checking where NSS calls C_Logout, but my guess is that it's and explicit call from PSM.....
(In reply to comment #22) > My guess is this is the result of the 'Clear Private Data (using the default > items that are checked)' call.... I suspect it calls logout. Yes... The browser is calling nsSecretDecoderRing::LogoutAndTeardown(): http://mxr.mozilla.org/seamonkey/source/security/manager/ssl/src/nsSDR.cpp#346
OK, so it's pretty clear the logout is happenning from a PK11_LogoutAll() call. NSS does have some code that delays checking the login status of a token for 1 second, but PK11_Logout explicitly clears that flag. If we are not in the delay period, PK11_IsLoggedIn() will call C_GetSessionInfo. Since we don't see a C_GetSessionInfo call between the C_Logout and the C_FindObjectInit calls, then either 1) that delay is not being cleared properly, or 2) PK11_IsLoggedIn is not being called. The latter can happen if slot->needLogin is zero: > PRBool > pk11_LoginStillRequired(PK11SlotInfo *slot, void *wincx) > { > return slot->needLogin && !PK11_IsLoggedIn(slot,wincx); > } > > /* > * make sure a slot is authenticated... > * This function only does the authentication if it is needed. > */ > SECStatus > PK11_Authenticate(PK11SlotInfo *slot, PRBool loadCerts, void *wincx) { > if (pk11_LoginStillRequired(slot,wincx)) { > return PK11_DoPassword(slot,loadCerts,wincx); > } > return SECSuccess; > } and http://mxr.mozilla.org/seamonkey/source/security/nss/lib/pk11wrap/pk11auth.c#690 Both of those conditions seem unlikely, but they appearantly are occuring. It would be good to set a breakpoint a PK11_LogoutAll() and look at the Database slot values of slot->needLogin and slot->lastLoginCheck (the easiest way to find the database slot is to step through the loop looking at mlp->module->slots[i]->token_name) I'm most interested in the value of slot->lastLoginCheck after the logout call(expected values of these 2 variables: needLogin=1 lastLoginCheck=0). The next thing would be to set a breakpoint at PK11_Authenticate, looking for calls where the slot is the database slot (slot->token_name), and look at the same 2 values (slot->needLogin=1 and slot->lastLoginCheck=0). My current hypothesis is needLogin is incorrectly set to '0'. bob
Justin wrote: > The browser is calling nsSecretDecoderRing::LogoutAndTeardown(): Why is it doing that? Isn't that the immediate cause of the other problems? Up until that point, there has been no NSS error that says anything about the user being logged out. Then the browser calls Logout and Teardown, and after that, (not surprisingly) the browser behaves as if softoken is logged out. This bug complains that the softoken is logged out. But Justin says that's because the browser told it to do so. So, at this point, I think the onus is on Justin to tell us why. I suspect that LogoutAndTeardown call is an inappropriate response to some other condition.
To put it another way, it isn't "unexpected" that the softoken is logged out after the browser calls that function. So, at a minimum, this bug description needs to be changed. We now know that the logout is the browser-initiated consequence of some other event or state. The question becomes: what is that other event or state? And is that an NSS bug or a browser bug? Given that Bob says that the C_EncryptFinalize is not reported as a failure higher up, I doubt that's the cause. But it is the last thing logged before the C_Logout calls.
Nelson, It's true the token is logged out, the problem is the SDR code should then try to reauthenticate, The point of failure is beyond and explicit PK11_Authenticate() call. I now have an annotated list of actual pk11wrap calls mapping to the relevant PKCS #11 calls, and now have a theory about what is going on... Hopefully I'll be able to create a short NSS test case. It's pretty clear that this test fails because we are starting with an uninitiallize database. I can see that we do the explicit PK11_InitPin call which will initialize the database. This call should also set the slot to needLogin mode. Setting the pin does and explicit C_Login without checking the value of 'needLogin' since it knows 1) it needs to log in since the token was explicitly logged out to log in as SSO, and 2) because we just successfully initialized the PIN, so the token must be a needLogin token. If we aren't properly adjusting the low level state to need login after setting the PIN, then it's possible that needLogin will be set incorrectly and once you explicitly log out the token, you will not be able to log back in until you restart. bob
Status: NEW → ASSIGNED
Attached file Annotated log. —
I'm now convinced looking in the log that the problem seems to be the failure of pk11wrap to properly update needLogin after the InitPIN (which probably translates to a failure in softoken to Properly update the value.
I've built my test case, and the above case fails, but now I have a new theory, which also involves softoken and the InitPIN case..... Looking back at the instructions, there isn't actually a master password set, so the database goes from uninitialized to no pin. However that transition is not properly managed in softoken, and it incorrectly forgets the DB password (which is a PBE based on the password "") when we logout. This causes the external code to (correctly) believe it doesn't need a password, but internally it believes it is logged out.
This patch to the NSS test tool dbtest (mozilla/security/nss/cmd/dbtest/dbtest.c). Can produce the problem. dbtest -i -p mypass -d /freshdirectory /* works */ dbtest -i -d /freshdirectory /* does not */ I should have the problem tracked down and fixed shortly...
Attached patch Test patch — — Splinter Review
Just, can you verify this patch works. I'll shortly attach a new one that updates the NSS test suite
Comment on attachment 313655 [details] [diff] [review] smaller test case Bob, I think this patch adds an important test feature to this program, and I'd really like to see this new test feature get checked in. But I have some issues with the implementation. 1. Prior to this patch, the function main called "exit(n)" in some paths, and in others it set a return value and returned it. I believe those are equivalent, within the function main. Calling exit(1) has the same effect as main returning the value 1. Both methods set the value returned by the program. The problem is that value 1 is intended to mean something different when returned than when passed to exit. And various calls to exit use the same value for different meanings. Similarly, other returned values come from two overlapping number spaces, making the return values ambiguous. The function main defines a variable "ret" if type "Error", which is an enum defined in modutil/error.h. The variable ret is the value returned by main (when main doesn't call exit). Prior to this patch, the function main would set that variable only to values defined in that enum, e.g. ret= DIR_DOESNT_EXIST_ERR; // value 18 ret=NSS_INITIALIZE_FAILED_ERR; // value 46 ret=SUCCESS; // value 0 (SUCCESS is a #define synonym for NO_ERR, which is a member of that enum, having the value zero.) But when main called exit, it always used the value 1, which is defined in the Error enum as: INVALID_USAGE_ERR It would return 1 even when the error being indicated was a leak detection or a shutdown failure. The return value of 1 had at least two distinct meangings. Now THIS PATCH adds YET ANOTHER set of small integer return values. It sets ret to these values: Statement value from Error enum ret = 1; // INVALID_USAGE_ERR, ret = 2; // UNEXPECTED_ARG_ERR, ret = 3; // UNKNOWN_OPTION_ERR, ret = 4; // MULTIPLE_COMMAND_ERR, However what the program means for these values are: 1 "Failed to Init DB:" 2 "New DB did not log in after init" 3 "New DB Did not initalize" 4 "Could not find generated key:" And this patch adds yet another place where it calls exit(1) with yet another meaning. In this new case, 1 "Could not generated symetric key:" With this patch, the program return value of 1 has at least 4 distinct meanings, and the values 2, 3, & 4 do not mean the meanings defined in the Error enum. So the issues are: 1. Each value returned from main or passed to exit should have one single meaning, regardless of which way it is returned. 2. The values returned should not be inconsistent with the values in the Error enum 3. main should try to be consistent, and use the same method (return or exit) in all paths. I would prefer it to be the return method.
Attached patch Patch with test case in all.sh (obsolete) — — Splinter Review
Attachment #313715 - Flags: review?(nelson)
My new patch includes some of nelson's comments, but probably not all. In cleaning up, I incorporated some of the error.h values. I did not clean up the pre-existing exit(1), nor the new exit(10)....
(In reply to comment #31) > Just, can you verify this patch works. I'll shortly attach a new one that > updates the NSS test suite Yep, this now works, with the steps to reproduce from comment 17!
This puts all but the pre-existing exit 1 in the same space. There are still some exit points that have the same error, but it should affect the ability of the test case. The test is now quite chatty and understanding failures from logfile should be easier.
Attachment #313715 - Attachment is obsolete: true
Attachment #313722 - Flags: review?
Attachment #313715 - Flags: review?(nelson)
Attachment #313722 - Flags: review? → review?(nelson)
Comment on attachment 313722 [details] [diff] [review] Test case cleanup Thanks, Bob. This is WAY better.
Attachment #313722 - Flags: review?(nelson) → review+
Checking in cmd/dbtest/dbtest.c; /cvsroot/mozilla/security/nss/cmd/dbtest/dbtest.c,v <-- dbtest.c new revision: 1.7; previous revision: 1.6 done Checking in lib/pk11wrap/pk11auth.c; /cvsroot/mozilla/security/nss/lib/pk11wrap/pk11auth.c,v <-- pk11auth.c new revision: 1.9; previous revision: 1.8 done Checking in tests/dbtests/dbtests.sh; /cvsroot/mozilla/security/nss/tests/dbtests/dbtests.sh,v <-- dbtests.sh new revision: 1.16; previous revision: 1.15 done bobs-laptop(166) Checked in.
Closing so the status in the NSS 3_12 RC1 tracking bug is updated. Firefox will see the change when NSS_3_12_RC1 is dropped in.
Status: ASSIGNED → RESOLVED
Closed: 17 years ago
Resolution: --- → FIXED
Target Milestone: --- → 3.12
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: