Open Bug 1267539 Opened 9 years ago Updated 3 years ago

Strange error message in error console: Couldn't decrypt string.

Categories

(Thunderbird :: Security, defect)

45 Branch
x86
Linux
defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: ishikawa, Unassigned, NeedInfo)

Details

(Keywords: sec-audit)

Attachments

(19 files, 1 obsolete file)

235.25 KB, image/png
Details
231.02 KB, image/png
Details
228.69 KB, image/png
Details
342.96 KB, image/png
Details
283.41 KB, image/png
Details
232.96 KB, image/png
Details
254.99 KB, image/png
Details
88.13 KB, image/png
Details
7.27 KB, text/plain
Details
120.60 KB, image/png
Details
257.69 KB, image/png
Details
258.62 KB, image/png
Details
6.83 KB, text/plain
Details
23.49 KB, text/x-log
Details
264.93 KB, image/png
Details
19.25 KB, text/x-log
Details
6.75 KB, text/plain
Details
257.50 KB, image/png
Details
4.60 KB, text/plain
Details
I may be seeing something sinister going on. Using 32-bit TB 45 (US English) under Debian GNU/Linux 64-bit. The message in question: Timestamp: 2016年04月26日 03時23分27秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 I am not using any crypt feature myself as far as I am concerned, and I don't think I saw this message in the previous version. I see the same message ocurring in tandem. Today it occurred 10 times in a row. The timestamp is the same for all the messages and I think it must have something to do with a single e-mail message. But I have no idea what the e-mail message is (lack of context). Ugh! The code that prints the error suggests that it is part of decrypt operation to show the stored password something. Is it possible that there is a random spam e-mail that somehow triggers such java code to obtain ??? saved password or what? // If the user clicks Cancel, we get NS_ERROR_NOT_AVAILABLE. // If the cipherText is bad / wrong key, we get NS_ERROR_FAILURE // Wrong passwords are handled by the decoderRing reprompting; // we get no notification. if (e.result == Cr.NS_ERROR_NOT_AVAILABLE) { canceledMP = true; throw Components.Exception("User canceled master password entry", Cr.NS_ERROR_ABORT); } else { ***=> throw Components.Exception("Couldn't decrypt string", Cr.NS_ERROR_FAILURE); } } finally { I don't have any suspicious add-on. - CompactHeader - Filter of filters - Google search for thunderbird - lighgtening - Remove Duplicate Messages (alternate) - ViewAbout <--- Could this be it? I have disabled to see how it goes. - Confirm-Address (non-official version adapted to TB 45) Note that the date/time in the error message 03:23:27 is when I am not at the computer... Very puzzling. Again, I did not see this message with ESR 38.x TIA
OK, come to think of it, trying to fetch e-mail obviously causes TB to use the stored password, but then it is a matter of why it fails then for no apparent reason?
Wait a second, for this particular installation of TB45, I did not store the password for pop3 server. I need to type in the POP3 password at each startup time. So if the error is about decrypting the password, then it ought to be this typed password (stored in a crypted manner for the duration of the session) (?). Again, not seeing this message previously makes me wonder what is going on. TIA
Keywords: sec-audit
Things get stranger: I disabled "ViewAbout" add-on, and kept TB running overnight. Surprise, at the same hour/minute, the strange error was recorded in Error Console of TB 45 (32-bit). Timestamp: 2016年04月27日 03時23分28秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 Well, it is actually one second off: this morning's is 03:23:28, but the previous one is 03:23:27. I checked crontab of the said PC, but there is no entry near that time of the day. I checked extra accounts in the TB installation: over the years, there have been a few extra accounts added to it, but they remain unused for most of the time. Also, there server settings is to check for new messages every 10 minutes. If a password is going to be used and then the saved password could not be decrypted (?), then the error console would have been filled with similar messages. OK, so I looked for a message that may have arrived around 03:23:28. It is not easy to figure out what message has a close timestamp on Received line, but as far as I can tell (I checked the suspicious e-mails that has the sent time stamp of last 24 hours. There does not seem to be one. If an older e-mail is sent to my server just before the time the problem occurred due to some delay, etc., I may have missed it. (I have not checked newsfeed, but I think I only get the articles when I access the newsgroup. As I mentioned, at 03:23 in the morning, nobody is at the console. Or is anyone? Hmm... The desktop is protected by password. I will check if there is someone who enters the office... But again, the same hour/minute suggests it is automatically repeated event.) I have begun to suspect that an occurrence at the same hour/minute (just one second difference) suggests that it is a local issue. Short of inserting code into rypto-SDR.js, is there a way to obtain the full stack dump to see what code is invoking this decrypt operation? That Japan where I live is going to enter a week long holiday period is no help, too. I probably shut down this computer on Friday night and won't be able to test this again until middle of May. BTW, TB 45 under Windows 10 on another PC does not show such strange error: I checked there. TIA
(In reply to ISHIKAWA, Chiaki from comment #3) > ... > I have begun to suspect that > an occurrence at the same hour/minute (just one second difference) suggests > that it is a local issue. > > Short of inserting code into > rypto-SDR.js, is there a way to obtain the full stack dump to see what code > is invoking this decrypt operation? Maybe Kaie or nonono will have an idea
Flags: needinfo?(o.e.ekker)
Flags: needinfo?(kaie)
If this happens each day at the same time, maybe an auto-update check for Thunderbird or one of its add-ons is causing it? Try disabling these one at a time to see if the error stops. Otherwise maybe add logging for each protocol as described here, to help pinpoint where the problem occurs: http://kb.mozillazine.org/Session_logging_for_mail/news
Flags: needinfo?(o.e.ekker)
The SDR is where we store encrypted saved passwords. A known scenario how a failure to decrypt can happen: - user sets a master password - user allows to save passwords - user forgets master password - user deletes the file that contains the private key related to the master password (e.g. key3.db) from the profile directory - encrypted passwords are still there, but can no longer be decrypted Might something like this have happened?
Flags: needinfo?(kaie)
(In reply to Onno Ekker [:nONoNonO UTC+1] from comment #5) > If this happens each day at the same time, maybe an auto-update check for > Thunderbird or one of its add-ons is causing it? Try disabling these one at > a time to see if the error stops. > Otherwise maybe add logging for each protocol as described here, to help > pinpoint where the problem occurs: > http://kb.mozillazine.org/Session_logging_for_mail/news I will see what I can do. (In reply to Kai Engert (:kaie) from comment #6) > The SDR is where we store encrypted saved passwords. > > A known scenario how a failure to decrypt can happen: > - user sets a master password > - user allows to save passwords > - user forgets master password > - user deletes the file that contains the private key related to the master > password > (e.g. key3.db) from the profile directory > - encrypted passwords are still there, but can no longer be decrypted > > Might something like this have happened? As far as I can tell, I simply upgraded TB and did NOT changed any setting (is what I *think* I did. Maybe I should delete ~/thunderbird directory and try again? ) Beside, if some of the scenarios took place, I am a little surprised because whenever POP3 server is contacted every 10 minutes (that is my setting) to check for pending e-mail, why doesn't TB print the same error repeatedly? [assuming that pop3 check decrypt saved password afresh each time pop3 server is accessed. TB does not keep the decrypted password in memory forever, or does it? ] TB printed the problematic message only at 03:23 (in the morning), and so I suspect auto-update or some daily activity (but why at 03:23?) might be to blame as noted in comment 6. But I need to do some investigative work by following the suggestion in comment 6 to see if there would be any smoking gun. TIA
I have not done the procedure mentioned in comment 6 yet. I obtained the same error again (11 times in a row) at 05:07:53 this morning. Timestamp: 2016年04月28日 05時07分53秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 I am going to disable - auto update and log "POP3:5, IMAP:5, SMTP:5, NNTP:5, nsHttp:5, MIME:5 or LDAP:5, " with timestamps. This coming Monday, I will report what I will find out by then. TIA -
I just notice that the "Message" entries in TB's error console do NOT have the timestamp (some have time string as part of the message, but not all of them.) "Errors" and "Warnings" have proper timestamps shown at the rightmost margin. We should have timestamps for "Message" entries, too. I noticed this while trying to associate the messages related to auto update to the data/time mentioned in this bugzilla entry. TIA
Hi, I disable update process by following http://kb.mozillazine.org/Session_logging_for_mail/news. Well, I think I followed it. But still I get the strange errors as follows. (YES, I restarted TB after setting the environment variable to log protocol events, and even saved the output using "script" command to a new file just in case the log will scroll up the console tty window.). The error messages still appear. 11 instances of the message at April 29, 06:30:53 Timestamp: 2016年04月29日 06時30分53秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 11 instances of the message at April 30, 11:01:40 11 instances of the message at May 1, 16:51:40 Each time, it appears 11 times. So it must be related to something. I think the time shown is in Japan Standard Time (JST). I just checked a few error messages occurring and recorded using the local JST. I checked the console tty window where I invoked TB 45 after setting the environment variable NSPR_LOG_MODULES to log protocol event. Somehow the event log there is printed using UTC as opposed to JST. My aim is to find events related, then, to the following UTC date/time ======================================= UTC JST --------------------------------------- April 28, 21:30:53 April 29, 06:30:53 (1) April 30, 02:01:40 April 30, 11:01:40 (2) May 1, 07:51:40 May 1, 16:51:40 (3) There is no event for date/time (1) The closest events are as follows: 2016-04-28 21:22:45.546631 UTC - -147044608[f7130180]: POP3 sink: [this=d5a5cce0] ReleaseFolderLock haveSemaphore = FALSE 2016-04-28 21:32:35.869540 UTC - -147044608[f7130180]: POP3: [this=dbfcbd20] LoadUrl() 2016-04-28 21:32:35.869595 UTC - -147044608[f7130180]: POP3: [this=dbfcbd20] Initialize() There is no event for date/time (2). The closest events are: 2016-04-30 02:00:25.634298 UTC - -147044608[f7130180]: nsHttpHandler::Observe [topic="network:link-status-changed"] 2016-04-30 02:04:28.419939 UTC - -147044608[f7130180]: POP3: [this=dbfcc980] LoadUrl() There is no event for date/time (3). The closest events are: 2016-05-01 07:35:52.730147 UTC - -147044608[f7130180]: POP3 sink: [this=d5a23620] ReleaseFolderLock haveSemaphore = FALSE 2016-05-01 07:58:20.539349 UTC - -147044608[f7130180]: POP3: [this=dbfcc2c0] LoadUrl() Hmm. I am stumped. BTW, I am uploading the preference setting involving "update". Have I disabled auto update correctly? I thought I followed the steps in the said URL, but not sure now. Any other ideas?
Somehow the previous upload attemp failed to recognize PNG format. So here it goes again.
Attachment #8747607 - Attachment is obsolete: true
I still had - CompactHeader - Confirm-Address (non-official version adapted to TB 45) - Filter of filters - Google search for thunderbird - lighgtening - Remove Duplicate Messages (alternate) I will disable - Confirm-Address (non-official version adapted to TB 45) - Filter of filters - Remove Duplicate Messages (alternate) and leave - CompactHeader - Google search for thunderbird - lighgtening The remaining three are more or less the standard recommended addons if I am not mistaken. Let me see what happens. I will report back on Friday.
One thing I have not done. If the error messages still persist on Friday, I will rename ~/thunderbird and create a new ~/thunderbird directory and see if it improves the situation. Maybe I should have done that earlier, but now that I have disabled the add-ons (except for the last three ones), I feel like testing disabling the reaming three addons on Friday and do the renaming of the directory and re-installation on Monday (even if I get the messages still...). TIA
I think you're still set to check for updates for add-ons. Toggle extensions.update.autoUpdateDefault to false or go to Tools -> Add-on Manager -> "Gear Icon" and uncheck "Update Add-ons Automatically".
(In reply to Onno Ekker [:nONoNonO UTC+1] from comment #14) > I think you're still set to check for updates for add-ons. Toggle > extensions.update.autoUpdateDefault to false or go to Tools -> Add-on > Manager -> "Gear Icon" and uncheck "Update Add-ons Automatically". Will do on Friday. TIA
This is Friday in Japan. Actually Tuesday, Wednesday, and Thursday were national holidays here, and I am afraid that somehow my PC went into sleep during that time :-( I don't see any activity in Error cosole, no warning, no message, etc. Well, at least I just did go to Tools -> Add-on Manager -> "Gear Icon" and uncheck "Update Add-ons Automatically". I think, then, though, the description in So I will keep this PC in this state until Monday to see if the error still persists. I have still these addons. - CompactHeader - Google search for thunderbird - lighgtening (In reply to ISHIKAWA, Chiaki from comment #10) > > I disable update process by following > http://kb.mozillazine.org/Session_logging_for_mail/news. Well, I think I > followed it. > I meant to say I followed the procedure in an obscure mozilla support forum: sorry I can't find the URL now and searched for similar pages using google, but not sure which one was the one I selected. There are conflicting or outdated pages and so I wish someone wrote a definitive guide about stopping automatic update for someone who needs that for technical reasons (yes, I know disabling is undesirable). TIA
Over the weekend I did not get this strnage crypt failure error. However, I noticed one thing. My PC was not in sleep mode as I falsely concluded on last Friday. (In reply to ISHIKAWA, Chiaki from comment #16) > This is Friday in Japan. > Actually Tuesday, Wednesday, and Thursday were national holidays here, and I > am afraid that somehow > my PC went into sleep during that time :-( > I don't see any activity in Error cosole, no warning, no message, etc. > > Well, at least I just did I looked at the tty console where thunderbird was invoked. I got the log output by setting the environment variable: NSPR_LOG_MODULES=imap:5,pop3:5,smtp:5,nttp:5,nsHttp:5,mime:5,ldap:5,timestamp (The log was actually recorded into a file using linux's "script" command. It has become large like 240 MB.) That PC and thunderbird did not seem to be sleeping during last week means then the addon I disabled on Monday last week might have caused the strange message and so I am going to turn it back on one by one to see which addon is the likely culprit of producing the cryptic error message. I will enable - Confirm-Address (non-official version adapted to TB 45) - Filter of filters - Remove Duplicate Messages (alternate) in this order. My suspicion is that confirm-address and filter of filters are not guilty because they are likely to be invoked only at the time of user interaction (sending an e-mail or searching for filter rules that contain a search string), but you never know. So I will enable confirm-address today, filter of filters tomorrow, and remove duplicat messages (alternate). But since I have disabled the auto-update turning back them on may not cause the cryptic message to appear. In that case, then auto-update somehow produced the cryptic message. We will know the answer on Thursday. TIA
Did you download/inistall all the add-ons from AMO? If not, they might contain a pointer to an update.rdf containing a bad date. Add-ons installed from AMO don't have an updateURL entry in their install.rdf. You can try to see if a manual update check for each add-on triggers the same error. Right click an add-on and choose "Find Updates" and check the error console after each one. If no error shows up, the message is probably triggered by the add-on itself.
(In reply to Onno Ekker [:nONoNonO UTC+1] from comment #18) > Did you download/inistall all the add-ons from AMO? If not, they might > contain a pointer to an update.rdf containing a bad date. Add-ons installed > from AMO don't have an updateURL entry in their install.rdf. > > You can try to see if a manual update check for each add-on triggers the > same error. Right click an add-on and choose "Find Updates" and check the > error console after each one. If no error shows up, the message is probably > triggered by the add-on itself. Thank you for the tips. I think the error is very quite likely to be cause by Confirm-Address addon: a slightly out-of-band from the AMO version since the AMO version did not work with TB45 (!). AFter I wrote message in comment 17, I was busy attending meetings, etc., and then I checked error console, and not so long after TB was restarted, I got this "Couldn't decrypt string" messages in 11:35:17. I could not reproduce the error using "Find Update" as you suggested for each of the addons. So let me now try to figure out why this error message occurs. (At the same, time until we figure out the real cause of the bug, I think it is prudent to keep this "security" bug since it may be that it may be easy to exploit route for someone to use a password (for what is my mystery). Of course, once you allow an addon to run in TB, I suspect all bets are off... TIA
Somehow the issue has not appeared in the error message log: automatic update check is disabled. I am going to enable another addon. Remove duplicate Messages (Alternate) I have currently CompactHeader Google Search for Thunderbird Lightning Confirm-Address <--- has been enabled. I will see if Remove Duplicate Message (alternate) is going to trigger the issue again. (Others waiting to be reenabled is Filter of Filters and ViewAbout. But ViewAbout was not enabled at the time the messages started to appear. So I hope I can find the cause of the problem without enabling ViewAbout... ).
Hi, I am trying to corelate the recurring "Couldn't decrypt string" (with the Japanese timestamp) below Timestamp: 2016年05月18日 19時33分26秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 against a message in error console 1463587384344 addons.update-checker WARN Update manifest for {972ce4c6-7e08-4474-a285-3208198ce6fd} did not contain an updates property I *think* the first number is a timestamp of a sort. But when I simply try to convert this using UNIX time to date, I got a rather bogus result. For example, I tried conversion at the following site and bot Mon, 28 Mar 48349 19:12:24 GMT which is way too much into the future. What is this number before e this message? OTOH, this message has nothing to do with the cryptic error message since I found an etry after searching for the GUID in the message https://bugzilla.mozilla.org/show_bug.cgi?id=808361#c7 which mentions that this has something to do with the chrome manifest no longer has the update information for default theme or something like that. Right now, I have the opinion that it seems to be triggered by an add-on, Remove Duplicate Messages (Aternate) [a non-official patch created by someone], but it seems that the cryptic error message appears only once after a restart of TB, and I can't really figure out whether it is INDEED coming from this addon. The above update failure seems to suggest that the addon may be checking the update at its own convenient time (how that can be possible is beyond me), but again it may be related to the default packaging issue and not related to the addon. Maybe I really need to have a stack trace or something to figure out which add on is causing this. TIA
Maybe you can take a look at https://developer.mozilla.org/en-US/Add-ons/Setting_up_extension_development_environment and set some preferences to see more logging from add-ons. Especially setting extensions.logging.enabled to true may help as is gives logging when update check is performed.
(In reply to Onno Ekker [:nONoNonO UTC+1] from comment #22) > Maybe you can take a look at > https://developer.mozilla.org/en-US/Add-ons/ > Setting_up_extension_development_environment and set some preferences to see > more logging from add-ons. > Especially setting extensions.logging.enabled to true may help as is gives > logging when update check is performed. Thank you. Will do.
After setting the variable as in the suggested page and restarting TB, I obtained the screen dumps (first the error message) and warnings that might be related to the error message. This is the suggestion I followed in the referenced web page: > extensions.logging.enabled = true. This will send more detailed information > about installation and update problems to the Error Console. (Note that the > extension manager automatically restarts the application at startup > sometimes, which may mean you won't have time to see the messages logged > before the automatic restart happens. To see them, prevent the automatic > restart by setting the environment NO_EM_RESTART to 1 before starting the > application.) The first screenshot is the error message. It happens on May 24, 10:58:47 (Japan Standard Time). I need to co-relate the timestamp in the message window (screendumps will follow).
The messages in the top-most part of the "Messages" list. I am surprised to see that there are update entries for "disabled" addons, too. For eaple viewabout is disabled in my setup. confirm-address is a suspect and is enabled. gsearch is a standard addon suggested to use google for search engine. OK, there are a couple of dictionary updates, too. Since there are earlier messages that seem pertinent to the issue in this bugzilla, I will follow with another couple of screen dumps to show the rest of "Messages" list. Yes, again, I need to understand what the meaning of the timestamp(?) in the Messages Window. For example, in the second to the top-most entry, we see: 1464026396484 addons.xpi-utils DEBUG XPI Database saved, setting schema version preference to 17 I wonder what this 1464026396484 means. I have ruled out the possibility of this being a UNIX time. Can this be a X windows time stamp or whatever? Does anyone know? TIA
(In reply to ISHIKAWA, Chiaki from comment #26) > Created attachment 8755773 [details] > The messages in the error console for "messages" types. The second part (the > latest ones are shown first.) I wonder that fofs@zer.net is in the second screen dump. (Could be the one explicitly checked by one of the addons.) In the second screen dump, I now see the series of https accesses to check the version at "versioncheck-bg.mozilla.org/": But there are 14 such accesses while the "Couldn't crypt messages" were 11 in total. There have been a series of 11 such messages in tandem at each burst (all were within the same second.) So I am not sure how they could be related unless there is a message throttling mechanism that prevent a few similar error messages from teach the the Error console. Since the https: access may have something to do with the "Couldn't decrypt string" messages, I am uploading the third screen dump to show the remaining part of such https access "Messages" entries. This is the third screen dump.
I see in your screen dumps that you first filtered on Errors and now on Messages. Can you view all and see if there's a line containing the message Failed to decrypt string just before the error Couldn't decrypt string? Maybe that gives us some more information…
(In reply to Onno Ekker [:nONoNonO UTC+1] from comment #28) > I see in your screen dumps that you first filtered on Errors and now on > Messages. Can you view all and see if there's a line containing the message > Failed to decrypt string just before the error Couldn't decrypt string? > Maybe that gives us some more information… Aha. Will do tomorrow. I have been so accustomed to see the different categories of messages separately and I forgot that I can see them all at the same time :-) I can't wait! TIA
Hi, I am afraid that by the time, I got to look at the error console under the windows, the messages from yesterday and the day before seem to be gone (i.e., were purged from the internal ring buffer(?). Ouch. ), but I had another series of 11 messages and could see that there is a suspicious entry before their occurrence. Security Error: Content at moz-nullprincipal:{d8f5a66d-d4f1-4013-a66d-a112950ff1fa} may not load or link to mailbox:///new-hd1/extra/ishikawa/MAIL-DIR/Mail/smap.nifty.com/Inbox.sbd/0-0-0-0-0-0-OpenSource.sbd/TeXLive-ML-DIR?number=21203201&header=filter&part=1.2&filename=image001.png. BTW, it seemed that the series of errors happen about 28 hours apart for the last few days. I found it rather puzzling: Timestamp: 2016年05月19日 22時21分10秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 After about 27 hours 7 min 30 seconds. Timestamp: 2016年05月21日 01時27分41秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 After about 28 hours 7 min 56 sec. Timestamp: 2016年05月22日 05時35分37秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 After about 27 hours 54 min 48 sec. Timestamp: 2016年05月23日 09時30分25秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 The latest one is recorded after two days and 3 hours and 28 min 50 sec. 48 h + 3 h and 28 min 50 sec = 51 and 28 min 50 sec. It is not quite multiple of 27 or 28 hours. Timestamp: 2016年05月25日 12時59分15秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 I am sure that if the frequencies of occurrences in the past few days continues, then I will see more of them in the next few days and I can correlated other events with the errors. This is the first possible cause, but too bad that "Security Error" message does not have a timestamp to make the correlation very clear. TIA
Hmm... I think there is a bug in error console code. Today when I first look at Error console's "Errors" display, there were only errors from todays at 12:59:15. But later, when I list "All" messages and again select only "Errors" messages, I got the "NS_ERROR_FAILURE: Couldn't decrypt string" in the list. Which means that I can scroll down hopefully in the All list to look at what happened at previous errors!!! However, when I look at the "All" list, the log is cut off in the middle of the chunk of 11 error messages (only 10 of them were shown and the list ended there) and so I cannot see what may be there before the 11 error chunks. However, the errors were followed by the following: Security Error: Content at moz-nullprincipal:{397e8956-cd0e-45f9-895e-980363c5c98b} may not load or link to about:blank. It may be still too early to tell what is causing the errors. I will report back what I will find in the next few days. TIA
I am afraid that I need to read the source of confirm-address addon...
I found another pref that might help setting to true: signon.debug From looking at the source it seems that the error is triggered from the login system, but I have no idea why it happens at these intervals.
(In reply to Onno Ekker [:nONoNonO UTC+1] from comment #34) > I found another pref that might help setting to true: signon.debug > From looking at the source it seems that the error is triggered from the > login system, but I have no idea why it happens at these intervals. Thanks. I will enable this and see what I can find about this mysterious events at non-24 hour interval even :-)
I set signon.debug to "true". I am uploading other "signon" attributes just in case there are some fishy values. I am not sure what this SignonFilename signon.SignonFileName;58255371.s is all about. I will see if this new setting signon.debug;"true" will show some activity near when "Couldn't decrypt string" error message is recorded. I have noticed that there is already a login message at the startup of TB that checks the addon freshess, etc. TIA
Now the tell-tale sign that the decrypt string operation is part of login attempt??? I checked the addresses mentioned in the login: I have several accounts in the profile I am using. Some accounts were copied over from my old e-mail account to the present day profile. These hold old e-mails for preservaion/archiving purposes. I noticed that the address I sanitized in the attached log as 10.AAA.BBB.CCC in the attachment is mentioned as IMAP mail server of not-used-any-more account: this holds only archived e-mail, and the 10.AAA.BBB.CCC address is supposed to be an internal-only address and no server exists there. A few accounts define localhost (127.0.0.1) for POP access. These are either archived account and not used any more, or for testing purposes. One mail host, mail.XXXXXXXX.jp is defined for another account: this again is not used actively, but has old mail messages. Which means that TB 45.x started to print the error messages simply because it failed to log in to these accounts (but for what? Maybe to purge old files ??) But then why TB did not print "Couldn't decrypt" message before? - maybe the message printing was not in ESR 38.x ? - maybe the error routine was not called at all in 38.x ? - maybe whatever process/event that triggered the login attemp was not properly activated in ESR38, but now is actived in 45.x? Hmm... I see "nsLoginManager" and count of logins. Is it possible that this is part of some performance analysis or usage statistics gathering ??? I think I am going to run TB for the next few days to see if I can glean a little more. TIA
I just wondered why on earth "xxx.example.com" appears in the log. I searched around and one old account (for testing purposes?) possibly had "xxx.example.com" as the incoming pop server when it was created initially although it list "localhost" as the pop server: I say this because the account's Message Storage Local directory is "... omitted ../ishikawa/MAIL-DIR/Mail/xxx.example.com". Notice the last directory path in the above: it is "xxx.example.com". Probably I created this account initially with "xxx.example.com" as the server of pop mail server long time ago or something, but still it is a mystery for me why TB wanted to access this bogus xxx.example.com hostname today. Either TB is more chatty regarding errors, or its behavior to scan all the account (for may be outdated messages on the server that need purging) may have changed due to system-default change? TIA
Saw two bursts of "Could not decrypt errors on the weekend." I have upgraded addon "confirm-address" d to the latest official version (available may 30?) but still get "could not decrypt" error message a few minutes after restarting TB. (I have been using a beta distributed by one of the new authors.) So I disabled (not removed) "confirm-address" and removed already disabled "viewabout" addon and restarted TB to see if I will see the errors again in the next few days. TIA
I am stumped. I still get the error over the night. I only now have - CompactHeader - Google Search for Thunderbird - Lightning in my add on list. (There are DISABLED addons - confirm-address - enigmail - filter of filters - Remove duplicate messages (alternate) - Quote Colors <--- this one is incompatible with thunderbird 45.0 and automatically disabled. ) I am going to remove all the disabled addons, and remove google search for thunderbird and see if the problem appears. If so, maybe I should suspect that there may be some issues on Dictionaries update.(?) I have - British English Dictionary - Canadian English Dictionary - United States English Spell Checker Can it be my cert file(s) somewhere have been corrupted and I should re-install them? TIA
Now the plot thickens. I have been reporting this problem with the Japanized TB (Japanese menu, etc) under linux. On a different PC, where I use Japanese version of TB under Windows 10 64-bit, I think I have encountered a very serious, or maybe a simple programming issue reported a sinister behavior somehow. I have no idea what is going on. But I have a feeling this issue may be remotely related to the problem at hand. This morning I saw a very disturbing message (modal dialog), but I am sorry that I failed to save it. I was just woking up and failed to do the proper saving, etc. Basically, it said something about someone tried to install an addon (?) Please seek help from an administrator or something. (The message seemed to appear at 05:xx . Sorry, I failed to preserve it :-( So I am not even sure if it was 04:xx. The error console listing is in the attachment. It seems that probably the cert errors mentioned in the error console probably triggered the error dialog eventually. So maybe the panel was shown at 04:xx. Now I wonder if somehow the distributed Japanese binary tar/install of TB, etc. has a bad cert data somewhere. TIA
OK, on the said PC (WIndows 10), TB has the following addons. Filters of filters Lightning LookOut and disabled Confirm Address I think I would remove Filters of filters, Confirm Address and Lookout to see if such a message would recur on that computer. That the strange behavior occurs only once a day makes the tracing rather difficult so far. TIA
I am stumped. Under linux, I left TB 45.0 running (gasp, it has not been updated to 45.1.1 series???) and there are only Compact Headers and Lightening addon (+ three dictionaries, and a disabled theme other than the default theme) and still got this "Couldn't decrypt string" message in the wee hours of morning (03:xx, JST). But I have just upgraded TB to 45.1.1 using the update button in "About Mozilla Thunderbird" panel. Let me see if this solves the strange issue. In any case, this problem was not observed under ESR38.x (the previous major update) and so either the new bug has arrived or the internal checking and error messages are more verbose. TIA
HI, OK, I think I have narrow it down to something like below. TB 45.1.1 under linux 64-bit (Debian GNU/Linux) 1: addon(s) ... Only have lightning and Compact header 2: Dictionaries ... British English Dictionary, Canadian English Dictionary and United States Spellchecker 3: Theme(s) Only the Default theme... (There was a disabled X11 Aqua theme, now being removed.) I still get the error: Error console showed a couple of series of "Could not decrypt string" messages over the weekend, and I also saw such a series this afternoon. Timestamp: 2016年06月06日 12時47分49秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 The afternoon series was preceded by version check operation, I think. See the error console screen dump. (I am afraid that my screen dump had the older entries first before. I fixed it by flipping the order.) and the tty window dump of the terminal emulator within which Thunderbird was invoked. Will remove "compact header" addon now and see if I still get the error. If not, then "compact header" may be to blame...
The Couldn't decrypt string messages are preceded by versioncheck-gb.addons.mozilla.org access and related processing.
I am afraid that I swapped the uploaded file: this one shows he beginning of the series which showed that the messages are preceded by the version check operation. The previous one showed that the series was followed by addon update operation.
Please note that the login time recorded in tty console where thunderbird is invoked is recorded in UTC whereas the Error console messages are stamped with Japanese Standard Time (UTC + 09 hours). TIA
I now have only lightning addon, but I still get this strange error. However, I may have hit upon a possible cause (?) Today, I had seen this strange message at 15:26:10 JST (which would 06:26:10 UTC). Timestamp: 2016年06月07日 15時26分10秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 By checking the tty window log dumped by TB, I found the following. 016-06-07 09:22:17.693586 UTC - -147245312[f7135180]: POP3: [this=d30d5080] Entering state: 23 2016-06-07 09:22:17.694936 UTC - -147245312[f7135180]: POP3: [this=d30d5080] Entering state: 25 console.log: nsLoginManager: Searching for logins matching host: mailbox://xxx.example.com formSubmitURL: httpRealm: mailbox://xxx.example.com console.log: Login storage: _searchLogins: returning 0 logins console.log: Login storage: _findLogins: returning 0 logins 2016-06-07 09:27:50.740645 UTC - -147245312[f7135180]: POP3: [this=da828e40] Connecting to server smap.gazonk-foobar.example.com:1110 2016-06-07 09:27:50.795784 UTC - -147245312[f7135180]: POP3: [this=da828e40] Entering NET_ProcessPop3 40 gazonk-foobar.example.com is actually a real server name, changed for privacy reasons. However, the above: mailbox://xxx.example.com is as printed by TB (!)l Now, I am not sure where this xxx.example.com comes from. It may be that I set this bogus/fake domain name for testing purposes before, but as far as I can tell there is NO current account that uses this mail server name. OK, one account seems to have used this server name (xxx.example.com) because its local directory is set to /new-hd1/extra/ishikawa/MAIL-DIR/Mail/xxx.example.com which suggests that this local account once used this bogus/fake account for testing purposes, etc. But it no longer uses the fake server. It points to localhost at port 110 for pop3 mail server. (ESR 38 did not check access errors or did not access it, but TB45 somehow suddenly begins to access this dormant account: maybe some default setup has changed under our feet?) I think TB 45.x series either - checks and print some error conditions more verbosely, OR - it looks at an incorrect entry somewhere which was not looked up/evaluated before. (But I am not sure where.) In the previous ESR, I don't get these errors... Just in case, I am going to remove the remaining three dictionaries so that the update for these may not be related to the observed errors. TIA
Attached file tty console log
I suspect this is not an add-on problem. I have removed all addons and dictionaries and only "lightning" remains. But I still get the error message in error console. I suspect this may NOT be the sinister activity after all, but may be something in lightning and/or some build-in telemetry thing? Background: Today, I got a series of following errors (11 of them in tandem) at 17:49:28 (Japan Standard Time) Timestamp: 2016年06月08日 17時49分28秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 From the tty console dump (from the tty emulator where thunderbird was invoked) I saw the following events: These are just before and after the timestamp. 17:49:28 (JST) is 08:49:28 (UTC) It seems to be that "console.log: nsLoginManager: Getting a list of all logins" starts some kind of data collections for gathering telemetry or something ? Also please notice the following lines. console.log: Login storage: _searchLogins: returning 43 logins (this message seems to be related to an activity that does not seem to generated couldn't decript string message) and console.log: Login storage: _getAllLogins: returning 32 logins. (This one seems be related to an activity that has generated the couldn't decript string message) So this may NOT be the sinister activity after all, but may be something in lightning and/or some build-in telemetry thing? I am attaching the log (tty dump).
I think it is reproducible, of a sort. I am attaching a screen dump of error console, and the tty window dump. Basically, this is a rehash of yesterday's. I am repeating the previous comment: Now I have only lightning and default theme. I suspect that this may have something to do with a fake/stale account that may have a strange old server information somewhere in prefs (?) (As I mention, one account that was created for testing and archiving purposes once placed xxx.example.com as a dummy pop3 server name, but now it points to localhost. the reference to xxx.example.com suggests that there is something related to this in my configuration presumably in prefs directory. However, under ESR38, this never caused the strange message "Couldn't decrypt string" message. I am curious if TB now with an eager telemetry tries to locate various possible login attempts (?): I am not sure why nsLoginManager is doing "Searching for loings match host".) If telemetry is doing this, I think it is a little too nosy (but I am not sure which module is doing this anyway.)
If only someone can say with a confidence that this is not a security issue, but is caused by "blah, blah, blah...".
_searchLogins returns 43 logins, while _getAllLogins only returns 32 logins, the difference is 11, which is the number of error messages you see. I'm not sure though where/when this is called. Do you maybe have sync enabled? Can you check in Help -> Troubleshooting Information how many accounts are listed there? Do you see any accounts that shouldn't be there? Maybe you can attach the troubleshooting information here (without private data)?
Hi, (In reply to Onno Ekker [:nONoNonO UTC+1] from comment #53) > _searchLogins returns 43 logins, while _getAllLogins only returns 32 logins, > the difference is 11, which is the number of error messages you see. wow, good catch ! > I'm not > sure though where/when this is called. Indeed. I have no idea where/when this is called. Almost random. Sometimes very soon after a restart of TB. Sometimes, I have to wait for more than 24 hours. > Do you maybe have sync enabled? I don't think so, but let me check on Monday :-( I left the building where the PC in question is located. > Can you check in Help -> Troubleshooting Information how many accounts are > listed there? > Do you see any accounts that shouldn't be there? > Maybe you can attach the troubleshooting information here (without private > data)? Will do on Monday. TIA
>> Do you maybe have sync enabled? >I don't think so, but let me check on Monday :-( > I left the building where the PC in question is located. I do not find any preference for Sync. Am I missing something? Attached is the sanitized trouble-shooting info. Re Mail and News Accounts The following is the main account I use regularly. (Actually, it talks to POPmail proxy on the local host first). That is why I use port 1110.) It has been working flawlessly for many months. * account1: INCOMING: account1, , (pop3) 127.0.0.1:1110, plain, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true (Local Folders) account that seems to be created for TB always. * account2: INCOMING: account2, , (none) Local Folders, plain, passwordCleartext The following is a news account: * account3: INCOMING: account3, , (nntp) news.mozilla.org:119, plain, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true The following is an e-mail account from which I want to send out e-mails occasionally using a different from e-mail address. So in that sense I send out only, and set up dummy/fake incoming server. account4: INCOMING: account4, , (pop3) localhost:110, plain, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true *The following could be a suspect: carry-over from an old e-mail setting in the office. account5: INCOMING: account5, , (pop3) mail.different-gazonk-foobar.com.jp:110, plain, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true account6: INCOMING: account6, , (pop3) localhost:110, plain, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true *The following could be a suspect: carry-over from an old e-mail setting in the office. * account7: INCOMING: account7, , (imap) 10.AAA.BBB.CCC:143, plain, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true The following is an e-mail account from which I want sent out e-mails occasionally using a different from e-mail address to test conference paper submission system. So in that sense I send out only, and set up dummy/fake incoming server. * account10: INCOMING: account10, , (pop3) 127.0.0.1:110, alwaysSTARTTLS, passwordCleartext OUTGOING: , smtp.gazonk-foobar.com:25, plain, passwordEncrypted, true The # of dummy/archive accounts match the entries in the trouble-shooting listing. However, since some of the dummy accounts use the same localhost/port=110 (pop3) server setup, it is difficult to match them to the listing in troubleshooting listing. (I may try to use a different port # to differentiate the entries in the trouble-shooting listing: I wonder if they may result in a different error reporting.) TIA
A good news: The error is now reproducible by trying to show passwords ! OK, while am trying to tweak the account settings, it occurred to me that I should check whether the password settings are correct. And when I goto preference -> security -> saved passwords and clicked it, I see that there are flurry of dumps to error console about Timestamp: 2016年06月13日 12時32分19秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 There are two things I should mention. I have NOT saved mail accounts passwords in this TB installation (!) *HOWEVER*, there *are* http(s) and ftp passwords (in TB, that is). I am confused. The passwords entries have been updated (and last used) as Oct 3, 2011. So they have been there all along, and somehow suddenly began getting accessed in ESR 45.x series, I suspect. At least, I can regularly/repeatedly show the error finally (!) Timestamp: 2016年06月13日 12時36分09秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 I am attaching a error console listing about the error(s) that was logged this morning: these errors were preceded by Security Error: Content at moz-nullprincipal:{d4f68ede-5a0e-4c87-85b7-fc1813fa6e07} may not load or link to mailbox:///new-hd1/extra/ishikawa/MAIL-DIR/Mail/smap.gazonk-foobar.com/Inbox.sbd/0-0-0-0-0-0-OpenSource.sbd/TeXLive-ML-DIR?number=21203420&header=filter&part=1.2&filename=Signature.jpg. Incidentally, there was a similar run of errors that was also preceded by a similar mailbox: access. This may not be related to the counting the logins which was noticed last week, but now that the stored password(s) for ftp/http(s) may be related obviously (well, of course, it was obvious from the start but since I did NOT save mail account passwords in this TB installation), I was slow in checking the stored passwords (which were updated about 5 years ago and given that they have the time stamp of the same day, I think I must have imported this from an installation on a different PC.) Any thought?
Attached is the tty console log that is printed when I push [saved passwords]. The error logs in the tty console AND the messages in Error Console are the same as in recorded by the mysterious behavior of TB45.x. (The number of "Couldn't derypt string" in one tandem is 11 as in before.) I thought the issue was not quite security oriented, but now that the error messages that are printed to the tty log console from which thunderbird was invoked is the same as when I push [saved passwords] button, I suspect TB is basically tyring to obtain the saved password for WHAT!? Can anyone guess what in TB (telemetry or whatever) can be doing this??? OK, Japanese version of TB uses BING as a default search engine. Can it be doing something funny although I can't think of how such passive default engine setting can cause strange behavior. Or can a message received can trigger a behavior that has been described here, say an HTML-formatted e-mail message and that the whitelisted URL actually now contains a malicious JS or something that triggers the behavior? (I trust that no JS snippet is ever executed inside an e-mail client. But who knows?) TIA
To clarify "[show passwords]" is reached via the following menu items. (Edit -> Preferences -> Security -> Saved Passwords -> Show Passwords) Since the PC where the problem occurs is not powerful in terms of debugging CPU power (not fast, only 4 core, and not large cache), I will copy the profile to a different computer where I have been compiling and running TB under valgrind occasionally to see if I can find any run-time errors from the latest debug build (or maybe running TB under valgrind when I click "[show passwords]" to see if I can glean something. (I think it has 4 cores / hyperthreading = 8 virtual cores and 6MB cache). TIA
(In reply to ISHIKAWA, Chiaki from comment #58) > To clarify "[show passwords]" is reached via the following menu items. > (Edit -> Preferences -> Security -> Saved Passwords -> Show Passwords) > > Since the PC where the problem occurs is not powerful in terms of debugging > CPU power (not fast, only 4 core, and not large cache), I will copy the > profile to a different computer where I have been compiling and running TB > under valgrind occasionally to see if I can find any run-time errors from > the latest debug build (or maybe running TB under valgrind when I click > "[show passwords]" to see if I can glean something. > (I think it has 4 cores / hyperthreading = 8 virtual cores and 6MB cache). > I could re-create the strange error messages printed to Error Console and tty console where thunderbird is invoked on a different PC after oopying the profile to that computer. I also ran TB under valgrind to see if there is any glaring memory error which valgrind can detect, but there were no obvious suspects. Hmm... So now the question is WHAT is triggering the scan of saved passwords. I will look into loginmanager js file to see what is being done when the error messages are printed. It looks to me superficially doing something extra/unnecessary in my first scan. I need to verify how/when the code was updated to see if my observation of ESR38 (silent) vs ESR45 (verbose) fits with the change history. TIA
TB 45.2.0 and stil seeing the couldn't decrypt string, but I now suspect this may have something to do with no longer active account I have in my profile. I hope I can get down to the root cause within this year.
TB 45.5.0: I don't see the strange error message any more, and so am closing this myself. TIA
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WORKSFORME
Sorry, I was too eager to close long standing bug. The message still persists. I am sure it must have somethng to do with my profile, but still not getting enough contextual information from the error message is not very helpful :-( Timestamp: 2017年01月31日 18時48分48秒 Error: NS_ERROR_FAILURE: Couldn't decrypt string Source File: resource://gre/components/crypto-SDR.js Line: 146 There are no other/warning messages that can be corelated to this message. (Ouch, if we show "All" messages (Errors, Warnings and Messages), somehow the date/time information is not displayed on the screen (!?) How unuseful :-( (Messages are not shown with date/time and it seems "All" falls to the largest common denominator and does not show date/time.) TIA
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
This is 45.7.0 now under linux.

still seeing this?

Flags: needinfo?(ishikawa)

Unless you can reproduce this with a fresh profile, I wouldn't spend much time on it.
It was probably some sort of corruption.

(In reply to Wayne Mery (:wsmwk) from comment #64)

still seeing this?

The behavior / message was observed on a PC at the office.
Due to Covid-19 outbreak in Tokyo, I have been working from home and have not visited the office for several weeks now.
Once I will be back at the office, I will re-check.

I realize that I tested the problem on a different PC (which I believe is my home PC) in comment 59 after copying the problematic
profile from the office computer.
Unfortunately, my home PC has undergone extensive change due to a hardware error a few years ago. [from XEON CPU to RYZEN CPU]. I seem to have lost the copied profile during transition. Yes, I think I need to visit the office (maybe after June 20 when the current state of emergency warning / declaration is supposed to be lifted. But it has been extended just yesterday for another three weeks, and so I am not sure.)

With the better debug console of today, I think I can co-relate the error, if it happens, with what TB is doing. : Now I see "display timestamp" option in the tool menu shown at the upper right corner of debug console window, and all the error/warning/info lines seem to be accompanied by timestamp at the beginning of line for easy identification. That was not the case 4-5 years ago.

Flags: needinfo?(ishikawa)
Flags: needinfo?(ishikawa)
Group: mail-core-security
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: